Mar 25 06:01:13 katarynka go-librespot[27993]: time="2026-03-25T06:01:13+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Mar 25 06:01:13 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:13 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:13 katarynka volumio[27666]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Mar 25 06:01:13 katarynka volumio[27666]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 25 06:01:13 katarynka volumio[27666]: Error: socket hang up Mar 25 06:01:13 katarynka volumio[27666]: at connResetException (node:internal/errors:720:14) Mar 25 06:01:13 katarynka volumio[27666]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 25 06:01:13 katarynka volumio[27666]: at Socket.emit (node:events:526:35) Mar 25 06:01:13 katarynka volumio[27666]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 25 06:01:13 katarynka volumio[27666]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 25 06:01:13 katarynka volumio[27666]: code: 'ECONNRESET', Mar 25 06:01:13 katarynka volumio[27666]: response: undefined Mar 25 06:01:13 katarynka volumio[27666]: } Mar 25 06:01:13 katarynka volumio[27666]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 25 06:01:15 katarynka sudo[29052]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-25 06:00' Mar 25 06:01:15 katarynka sudo[29052]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:15 katarynka sudo[29052]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:15 katarynka volumio-remote-updater[622]: [2026-03-25 06:01:15] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 25 06:01:15 katarynka volumio-remote-updater[622]: [2026-03-25 06:01:15] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 25 06:01:15 katarynka systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:15 katarynka systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 25 06:01:15 katarynka systemd[1]: volumio.service: Consumed 1min 4.191s CPU time. Mar 25 06:01:15 katarynka systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 25 06:01:15 katarynka systemd[1]: dynamicswap.service: Deactivated successfully. Mar 25 06:01:15 katarynka systemd[1]: volumio.service: Scheduled restart job, restart counter is at 25998. Mar 25 06:01:15 katarynka systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 25 06:01:15 katarynka systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 25 06:01:15 katarynka systemd[1]: volumio.service: Consumed 1min 4.191s CPU time. Mar 25 06:01:15 katarynka systemd[1]: Started volumio.service - Volumio Backend Module. Mar 25 06:01:15 katarynka systemd[1]: dynamicswap.service: Deactivated successfully. Mar 25 06:01:16 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Mar 25 06:01:16 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:16 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:16 katarynka go-librespot[29112]: go-librespot daemon starting... Mar 25 06:01:16 katarynka go-librespot[29113]: time="2026-03-25T06:01:16+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:16 katarynka go-librespot[29113]: time="2026-03-25T06:01:16+01:00" level=debug msg="app state loaded" Mar 25 06:01:16 katarynka go-librespot[29113]: time="2026-03-25T06:01:16+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:01:17 katarynka go-librespot[29113]: time="2026-03-25T06:01:17+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:01:17 katarynka go-librespot[29113]: time="2026-03-25T06:01:17+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:01:17 katarynka go-librespot[29113]: time="2026-03-25T06:01:17+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:01:17 katarynka go-librespot[29113]: time="2026-03-25T06:01:17+01:00" level=info msg="zeroconf server listening on port 35533" Mar 25 06:01:17 katarynka go-librespot[29113]: time="2026-03-25T06:01:17+01:00" level=debug msg="obtained new client token: AAAARz88RsAwBK+i86wUMV6hvHxIwb9cyE0C6Uo6Gp9pSZx6bPT164TIQn2FN/meIL3DXfZT1y9QioExpjnZ8PJ2OZYs+ytayTHEHKHXs62A2EQZfazRkWl5bBVoxRC8qLtp2uOsKc/v4Bj+lTHXljD9Cfv+SHflNry1j8cgBwIe6UynJLmgYTKqgotzA7ZnVQN0dAYLpD23bQY7tO/ArBQOp2A056lZElkVTXarXB8s6iLcuqEwgrkQUsQ=" Mar 25 06:01:17 katarynka go-librespot[29113]: time="2026-03-25T06:01:17+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:01:17 katarynka go-librespot[29113]: time="2026-03-25T06:01:17+01:00" level=debug msg="completed keyexchange" Mar 25 06:01:17 katarynka go-librespot[29113]: time="2026-03-25T06:01:17+01:00" level=debug msg="completed challenge" Mar 25 06:01:18 katarynka go-librespot[29113]: time="2026-03-25T06:01:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:01:18 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:18 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:19 katarynka volumio[29097]: info: ------------------------------------------- Mar 25 06:01:19 katarynka volumio[29097]: info: ----- Volumio3 ---- Mar 25 06:01:19 katarynka volumio[29097]: info: ------------------------------------------- Mar 25 06:01:19 katarynka volumio[29097]: info: ----- System startup ---- Mar 25 06:01:19 katarynka volumio[29097]: info: ------------------------------------------- Mar 25 06:01:20 katarynka volumio-remote-updater[622]: [2026-03-25 06:01:20] [connect] Successful connection Mar 25 06:01:21 katarynka volumio[29097]: info: MYVOLUMIO Environment detected Mar 25 06:01:21 katarynka volumio[29097]: info: Plugin folders cleanup Mar 25 06:01:21 katarynka volumio[29097]: info: Scanning into folder /volumio/app/plugins/ Mar 25 06:01:21 katarynka volumio[29097]: info: Scanning category audio_interface Mar 25 06:01:21 katarynka volumio[29097]: info: Scanning category miscellanea Mar 25 06:01:21 katarynka volumio[29097]: info: Scanning category music_service Mar 25 06:01:21 katarynka volumio[29097]: info: Scanning category plugins.json Mar 25 06:01:21 katarynka volumio[29097]: info: Scanning category system_controller Mar 25 06:01:21 katarynka volumio[29097]: info: Scanning category user_interface Mar 25 06:01:21 katarynka volumio[29097]: info: Scanning into folder /data/plugins/ Mar 25 06:01:21 katarynka volumio[29097]: info: Scanning category music_service Mar 25 06:01:21 katarynka volumio[29097]: info: Plugin folders cleanup completed Mar 25 06:01:21 katarynka volumio[29097]: info: ------------------------------------------- Mar 25 06:01:21 katarynka volumio[29097]: info: ----- Core plugins startup ---- Mar 25 06:01:21 katarynka volumio[29097]: info: ------------------------------------------- Mar 25 06:01:21 katarynka volumio[29097]: info: Loading plugins from folder /volumio/app/plugins/ Mar 25 06:01:21 katarynka volumio[29097]: info: Adding plugin upnp to MyMusic Plugins Mar 25 06:01:21 katarynka volumio[29097]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 25 06:01:21 katarynka volumio[29097]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 25 06:01:21 katarynka volumio[29097]: info: Loading plugins from folder /data/plugins/ Mar 25 06:01:21 katarynka volumio[29097]: info: Loading plugin "system"... Mar 25 06:01:21 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Mar 25 06:01:21 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:21 katarynka volumio[29097]: info: Loading plugin "appearance"... Mar 25 06:01:21 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:21 katarynka go-librespot[29130]: go-librespot daemon starting... Mar 25 06:01:21 katarynka go-librespot[29134]: time="2026-03-25T06:01:21+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:21 katarynka go-librespot[29134]: time="2026-03-25T06:01:21+01:00" level=debug msg="app state loaded" Mar 25 06:01:21 katarynka go-librespot[29134]: time="2026-03-25T06:01:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:01:21 katarynka go-librespot[29134]: time="2026-03-25T06:01:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:01:21 katarynka go-librespot[29134]: time="2026-03-25T06:01:21+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:01:21 katarynka go-librespot[29134]: time="2026-03-25T06:01:21+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:01:22 katarynka go-librespot[29134]: time="2026-03-25T06:01:22+01:00" level=info msg="zeroconf server listening on port 36417" Mar 25 06:01:22 katarynka go-librespot[29134]: time="2026-03-25T06:01:22+01:00" level=debug msg="obtained new client token: AAClfg/nWQTB0zTTJ6bicrR4NiOdQbCStPSJm4E0tbbUdgj1PN+6NUkJ7kILPYDbyAfg0RqjlZC39/h8tTpsIQnpaHCV+WdO2XSIAvP0eNq0/So/KspaMJzP1bCwv3iCO9Thg8FG0fAzQgETMfVxeFm0myUxb2eGoMgDrtgv+QOLGqYNfKEWI5vOWP0r22vrVekdR5sLSZyzW66RJOphAlnzmWZYhPdUeWjZMIZCHrjxo+mThQusRYXq" Mar 25 06:01:22 katarynka go-librespot[29134]: time="2026-03-25T06:01:22+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:01:22 katarynka go-librespot[29134]: time="2026-03-25T06:01:22+01:00" level=debug msg="completed keyexchange" Mar 25 06:01:22 katarynka go-librespot[29134]: time="2026-03-25T06:01:22+01:00" level=debug msg="completed challenge" Mar 25 06:01:22 katarynka go-librespot[29134]: time="2026-03-25T06:01:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:01:22 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:22 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:23 katarynka volumio[29097]: info: Loading plugin "network"... Mar 25 06:01:23 katarynka volumio[29097]: info: Refreshing Cached IP Addresses Mar 25 06:01:23 katarynka sudo[29144]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 25 06:01:23 katarynka sudo[29144]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:23 katarynka sudo[29146]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 25 06:01:23 katarynka sudo[29146]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:23 katarynka sudo[29144]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:23 katarynka volumio[29097]: info: Loading plugin "services"... Mar 25 06:01:23 katarynka sudo[29146]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:23 katarynka volumio[29097]: info: Loading plugin "alsa_controller"... Mar 25 06:01:23 katarynka sudo[29154]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 25 06:01:23 katarynka sudo[29154]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:23 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 25 06:01:23 katarynka volumio[29097]: info: Loading plugin "wizard"... Mar 25 06:01:23 katarynka volumio[29097]: info: Loading plugin "networkfs"... Mar 25 06:01:23 katarynka volumio[29097]: info: Starting Udev Watcher for removable devices Mar 25 06:01:23 katarynka volumio[29097]: info: Ignoring mount for partition: boot Mar 25 06:01:23 katarynka volumio[29097]: info: Ignoring mount for partition: volumio Mar 25 06:01:23 katarynka volumio[29097]: info: Ignoring mount for partition: volumio_data Mar 25 06:01:23 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 25 06:01:23 katarynka volumio[29097]: info: Loading plugin "volumio_command_line_client"... Mar 25 06:01:23 katarynka volumio[29097]: info: Loading plugin "upnp"... Mar 25 06:01:23 katarynka volumio[29097]: info: [1774414883981] Starting Upmpd Daemon Mar 25 06:01:23 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 25 06:01:23 katarynka volumio[29097]: info: Loading plugin "my_music"... Mar 25 06:01:24 katarynka volumio[29097]: info: Loading plugin "mpd"... Mar 25 06:01:24 katarynka sudo[29154]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:24 katarynka volumio[29097]: info: Loading plugin "upnp_browser"... Mar 25 06:01:25 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Mar 25 06:01:25 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:25 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:25 katarynka go-librespot[29178]: go-librespot daemon starting... Mar 25 06:01:25 katarynka go-librespot[29179]: time="2026-03-25T06:01:25+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:25 katarynka go-librespot[29179]: time="2026-03-25T06:01:25+01:00" level=debug msg="app state loaded" Mar 25 06:01:25 katarynka go-librespot[29179]: time="2026-03-25T06:01:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:01:25 katarynka go-librespot[29179]: time="2026-03-25T06:01:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:01:25 katarynka go-librespot[29179]: time="2026-03-25T06:01:25+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:01:25 katarynka go-librespot[29179]: time="2026-03-25T06:01:25+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:01:26 katarynka go-librespot[29179]: time="2026-03-25T06:01:26+01:00" level=info msg="zeroconf server listening on port 41785" Mar 25 06:01:26 katarynka go-librespot[29179]: time="2026-03-25T06:01:26+01:00" level=debug msg="obtained new client token: AADEzo4cjlHaLNH668m9UCSUJBkIlpJu/u3wqfGHrjkTz8YU8a+IKFZjBK/2/anXpwt8W8iqpVWZj4mZ0hk2pmUIQi7xh8JBA+Jp37tNApN44JijV5nmxqmbtzALkOaNNeZpl1wAmlpzzKTQUnJwJ2ONsc9/hDqHN/1KACQT+g8bHDn5ZUt04WKbKgV7wjifH3pEX1s65OF6qeQyJR6evWcXDpLh26Vq7dRShPbLyWp30LdmWN2NX4os" Mar 25 06:01:26 katarynka go-librespot[29179]: time="2026-03-25T06:01:26+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 25 06:01:26 katarynka go-librespot[29179]: time="2026-03-25T06:01:26+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 25 06:01:26 katarynka go-librespot[29179]: time="2026-03-25T06:01:26+01:00" level=debug msg="completed keyexchange" Mar 25 06:01:26 katarynka go-librespot[29179]: time="2026-03-25T06:01:26+01:00" level=debug msg="completed challenge" Mar 25 06:01:26 katarynka go-librespot[29179]: time="2026-03-25T06:01:26+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:01:26 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:26 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:27 katarynka volumio[29097]: info: Starting UPNP Browser Mar 25 06:01:27 katarynka volumio[29097]: info: Loading plugin "alarm-clock"... Mar 25 06:01:28 katarynka volumio[29097]: info: Loading plugin "airplay_emulation"... Mar 25 06:01:28 katarynka volumio[29097]: info: Starting Shairport Sync Mar 25 06:01:28 katarynka volumio[29097]: info: Loading plugin "last_100"... Mar 25 06:01:28 katarynka volumio[29097]: info: Loading plugin "webradio"... Mar 25 06:01:28 katarynka volumio[29097]: info: Loading plugin "i2s_dacs"... Mar 25 06:01:28 katarynka volumio[29097]: info: Loading plugin "volumiodiscovery"... Mar 25 06:01:28 katarynka volumio[29097]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 25 06:01:28 katarynka node[29097]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 25 06:01:28 katarynka volumio[29097]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 25 06:01:28 katarynka node[29097]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 25 06:01:28 katarynka volumio[29097]: *** WARNING *** For more information see Mar 25 06:01:28 katarynka node[29097]: *** WARNING *** For more information see Mar 25 06:01:28 katarynka volumio[29097]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 25 06:01:28 katarynka node[29097]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 25 06:01:28 katarynka volumio[29097]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 25 06:01:28 katarynka node[29097]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 25 06:01:28 katarynka volumio[29097]: *** WARNING *** For more information see Mar 25 06:01:28 katarynka node[29097]: *** WARNING *** For more information see Mar 25 06:01:28 katarynka volumio[29097]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 25 06:01:28 katarynka volumio[29097]: info: Discovery: Started advertising with name: katarynka Mar 25 06:01:28 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 25 06:01:28 katarynka volumio[29097]: info: Loading plugin "spop"... Mar 25 06:01:29 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Mar 25 06:01:29 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:29 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:29 katarynka go-librespot[29189]: go-librespot daemon starting... Mar 25 06:01:29 katarynka go-librespot[29190]: time="2026-03-25T06:01:29+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:29 katarynka go-librespot[29190]: time="2026-03-25T06:01:29+01:00" level=debug msg="app state loaded" Mar 25 06:01:29 katarynka go-librespot[29190]: time="2026-03-25T06:01:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:01:30 katarynka go-librespot[29190]: time="2026-03-25T06:01:30+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 25 06:01:30 katarynka go-librespot[29190]: time="2026-03-25T06:01:30+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 25 06:01:30 katarynka go-librespot[29190]: time="2026-03-25T06:01:30+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 25 06:01:30 katarynka go-librespot[29190]: time="2026-03-25T06:01:30+01:00" level=info msg="zeroconf server listening on port 36383" Mar 25 06:01:30 katarynka go-librespot[29190]: time="2026-03-25T06:01:30+01:00" level=debug msg="obtained new client token: AAAYc2c6T3rLg6cyqsZ1Uvp9j8KM8lFfSKGNPd1VmxL9FaBvVWD2BywA8d8uhVIFNdS30U/6u1NoXo4gyfSZYTf1wjrI2Eap1eklBDItIBR7HT7y9HcU3uqRcdxyCY37m36U2SWUxUB2h0LwcgZIrAKgGCrJsPCWDSPb+Q0WvKmiHoJ8eKvs3OmA76U5B8Lf4HaKhKf0PqtNxH6XR/jCE29OGVPKDHn8/8JlLh7CsF93okr3Hg9IrgxCQXM=" Mar 25 06:01:30 katarynka go-librespot[29190]: time="2026-03-25T06:01:30+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:01:30 katarynka volumio[29097]: info: Loading plugin "outputs"... Mar 25 06:01:30 katarynka volumio[29097]: info: Loading plugin "albumart"... Mar 25 06:01:30 katarynka go-librespot[29190]: time="2026-03-25T06:01:30+01:00" level=debug msg="completed keyexchange" Mar 25 06:01:30 katarynka go-librespot[29190]: time="2026-03-25T06:01:30+01:00" level=debug msg="completed challenge" Mar 25 06:01:30 katarynka volumio[29097]: info: Plugin example_plugin is not enabled Mar 25 06:01:30 katarynka volumio[29097]: info: Loading plugin "inputs"... Mar 25 06:01:30 katarynka volumio[29097]: info: Loading plugin "updater_comm"... Mar 25 06:01:30 katarynka go-librespot[29190]: time="2026-03-25T06:01:30+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:01:30 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:30 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:30 katarynka volumio[29097]: info: Plugin mpdemulation is not enabled Mar 25 06:01:30 katarynka volumio[29097]: info: Loading plugin "rest_api"... Mar 25 06:01:30 katarynka volumio[29097]: info: Loading plugin "websocket"... Mar 25 06:01:30 katarynka volumio[29097]: info: Starting Socket.io Server version 1.7.4 Mar 25 06:01:31 katarynka volumio[29097]: info: Loading i18n strings for locale pl Mar 25 06:01:31 katarynka volumio[29097]: Updating browse sources language Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::initPlayerControls Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: Express server listening on port 3000 Mar 25 06:01:31 katarynka volumio[29097]: [Metrics] WebUI: 12s 625.34ms Mar 25 06:01:31 katarynka volumio[29097]: info: CoreStateMachine::resetVolumioState Mar 25 06:01:31 katarynka volumio[29097]: info: CoreStateMachine::getcurrentVolume Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::volumioRetrievevolume Mar 25 06:01:31 katarynka volumio[29097]: info: Cannot read play queue from file Mar 25 06:01:31 katarynka volumio[29097]: info: Volumio Network Manager: Network status updated: 2 Mar 25 06:01:31 katarynka volumio[29197]: Forking 3 albumart workers Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:01:31 katarynka volumio[29097]: info: VolumeController:: Volume=96 Mute =false Mar 25 06:01:31 katarynka volumio[29097]: info: CoreStateMachine::pushState Mar 25 06:01:31 katarynka volumio[29097]: info: CorePlayQueue::getTrack 0 Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::volumioPushState Mar 25 06:01:31 katarynka volumio[29097]: info: CoreStateMachine::updateTrackBlock Mar 25 06:01:31 katarynka volumio[29097]: info: CorePlayQueue::getTrackBlock Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::volumioRetrievevolume Mar 25 06:01:31 katarynka volumio[29097]: info: Setting Device type: Raspberry PI Mar 25 06:01:31 katarynka volumio[29097]: info: CoreStateMachine::setRepeat null single undefined Mar 25 06:01:31 katarynka volumio[29097]: info: CoreStateMachine::pushState Mar 25 06:01:31 katarynka volumio[29097]: info: CorePlayQueue::getTrack 0 Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::volumioPushState Mar 25 06:01:31 katarynka volumio[29097]: info: CoreStateMachine::setRandom null Mar 25 06:01:31 katarynka volumio[29097]: info: CoreStateMachine::pushState Mar 25 06:01:31 katarynka volumio[29097]: info: CorePlayQueue::getTrack 0 Mar 25 06:01:31 katarynka volumio[29097]: info: CoreCommandRouter::volumioPushState Mar 25 06:01:31 katarynka volumio[29097]: info: Completed loading Core Plugins Mar 25 06:01:31 katarynka volumio[29097]: info: Preparing to generate the ALSA configuration file Mar 25 06:01:32 katarynka volumio[29097]: info: Asound.conf file unchanged, so no further update is needed Mar 25 06:01:32 katarynka volumio[29097]: info: Output device has changed, restarting MPD Mar 25 06:01:32 katarynka volumio[29097]: info: Output device has changed, restarting Shairport Sync Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:01:32 katarynka sudo[29253]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 25 06:01:32 katarynka sudo[29253]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:32 katarynka volumio[29097]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 25 06:01:32 katarynka volumio[29097]: info: ___________ START PLUGINS ___________ Mar 25 06:01:32 katarynka sudo[29253]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:32 katarynka volumio[29097]: info: ControllerMpd::onStart: Initializing MPD Mar 25 06:01:32 katarynka volumio[29097]: info: Creating MPD Configuration file Mar 25 06:01:32 katarynka sudo[29254]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 25 06:01:32 katarynka sudo[29254]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 25 06:01:32 katarynka sudo[29264]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 25 06:01:32 katarynka systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 25 06:01:32 katarynka volumio[29097]: info: [1774414892439] CoreMusicLibrary::Adding element Serwery Mediów Mar 25 06:01:32 katarynka sudo[29264]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:32 katarynka sudo[29262]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 25 06:01:32 katarynka sudo[29262]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:32 katarynka sudo[29262]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:32 katarynka volumio[29097]: info: UPNP Browser: Client initialized successfully Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:01:32 katarynka systemd[1]: mpd.service: Deactivated successfully. Mar 25 06:01:32 katarynka systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 25 06:01:32 katarynka systemd[1]: mpd.service: Consumed 7.830s CPU time. Mar 25 06:01:32 katarynka systemd[1]: mpd.socket: Deactivated successfully. Mar 25 06:01:32 katarynka systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 25 06:01:32 katarynka systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 25 06:01:32 katarynka volumio[29097]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:01:32 katarynka systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 25 06:01:32 katarynka systemd[1]: Starting mpd.service - Music Player Daemon... Mar 25 06:01:32 katarynka volumio[29097]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 25 06:01:32 katarynka volumio[29097]: info: [1774414892756] CoreMusicLibrary::Adding element Last_100 Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 25 06:01:32 katarynka systemd[1]: mpd.service: Deactivated successfully. Mar 25 06:01:32 katarynka systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 25 06:01:32 katarynka volumio[29097]: info: [1774414892784] CoreMusicLibrary::Adding element Webradio Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 25 06:01:32 katarynka systemd[1]: mpd.socket: Deactivated successfully. Mar 25 06:01:32 katarynka systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 25 06:01:32 katarynka systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 25 06:01:32 katarynka systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 25 06:01:32 katarynka volumio[29097]: info: Initializing BBC Radios Mar 25 06:01:32 katarynka systemd[1]: Starting mpd.service - Music Player Daemon... Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 25 06:01:32 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:01:33 katarynka volumio[29097]: info: Creating Spotify config file Mar 25 06:01:33 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:33 katarynka volumio-remote-updater[622]: [2026-03-25 06:01:33] [connect] Successful connection Mar 25 06:01:33 katarynka sudo[29278]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 25 06:01:33 katarynka sudo[29278]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 25 06:01:33 katarynka sudo[29278]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:33 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Mar 25 06:01:33 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:33 katarynka volumio[29097]: info: Volumio Calling Home Mar 25 06:01:34 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:34 katarynka go-librespot[29305]: go-librespot daemon starting... Mar 25 06:01:34 katarynka go-librespot[29314]: time="2026-03-25T06:01:34+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:34 katarynka go-librespot[29314]: time="2026-03-25T06:01:34+01:00" level=info msg="zeroconf server listening on port 35387" Mar 25 06:01:35 katarynka volumio[29097]: info: Discovery: adding 4d616d77-6a8c-4da2-85a4-840d70f98e51 Mar 25 06:01:35 katarynka volumio[29097]: info: Discovery: Found device katarynka Mar 25 06:01:35 katarynka volumio[29097]: info: CoreCommandRouter::volumioGetState Mar 25 06:01:35 katarynka sudo[29323]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 25 06:01:35 katarynka volumio[29097]: info: CorePlayQueue::getTrack 0 Mar 25 06:01:35 katarynka sudo[29323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:35 katarynka sudo[29325]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 25 06:01:35 katarynka sudo[29323]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:35 katarynka sudo[29325]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:35 katarynka sudo[29325]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:35 katarynka volumio[29097]: info: MPD Permissions set Mar 25 06:01:35 katarynka volumio[29219]: Starting albumart workers Mar 25 06:01:35 katarynka volumio[29097]: info: MPD Permissions set Mar 25 06:01:35 katarynka volumio[29097]: info: VolumeController:: Volume=96 Mute =false Mar 25 06:01:35 katarynka volumio[29097]: info: CoreStateMachine::pushState Mar 25 06:01:35 katarynka volumio[29097]: info: CorePlayQueue::getTrack 0 Mar 25 06:01:35 katarynka volumio[29097]: info: CoreCommandRouter::volumioPushState Mar 25 06:01:35 katarynka volumio-remote-updater[622]: [2026-03-25 06:01:35] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774414893 101 Mar 25 06:01:35 katarynka volumio[29097]: 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: 1 Mar 25 06:01:35 katarynka volumio[29218]: Starting albumart workers Mar 25 06:01:35 katarynka volumio[29097]: info: Volumio called home Mar 25 06:01:35 katarynka volumio[29097]: info: Spotify config file written Mar 25 06:01:35 katarynka volumio[29097]: info: Discovery: this is already registered, 4d616d77-6a8c-4da2-85a4-840d70f98e51 Mar 25 06:01:35 katarynka volumio[29097]: info: Discovery: Found device katarynka Mar 25 06:01:35 katarynka volumio[29097]: info: CoreCommandRouter::volumioGetState Mar 25 06:01:35 katarynka volumio[29097]: info: CorePlayQueue::getTrack 0 Mar 25 06:01:36 katarynka sudo[29329]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 25 06:01:36 katarynka sudo[29329]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:36 katarynka systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 25 06:01:36 katarynka systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 25 06:01:36 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:36 katarynka volumio[29097]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka go-librespot[29331]: go-librespot daemon starting... Mar 25 06:01:36 katarynka sudo[29329]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:36 katarynka go-librespot[29332]: time="2026-03-25T06:01:36+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:36 katarynka go-librespot[29332]: time="2026-03-25T06:01:36+01:00" level=debug msg="app state loaded" Mar 25 06:01:36 katarynka go-librespot[29332]: time="2026-03-25T06:01:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:01:36 katarynka volumio[29097]: info: No need to fix Spotify hosts Mar 25 06:01:36 katarynka volumio[29217]: Starting albumart workers Mar 25 06:01:36 katarynka go-librespot[29332]: time="2026-03-25T06:01:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:01:36 katarynka go-librespot[29332]: time="2026-03-25T06:01:36+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:01:36 katarynka go-librespot[29332]: time="2026-03-25T06:01:36+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:01:37 katarynka go-librespot[29332]: time="2026-03-25T06:01:37+01:00" level=info msg="zeroconf server listening on port 35393" Mar 25 06:01:37 katarynka go-librespot[29332]: time="2026-03-25T06:01:37+01:00" level=debug msg="obtained new client token: AACilxQg+RnuRcdiTuZipUJQ+7H4wOme7LO1BW1xiPW4yqGrww3UuBAMlqZT3qbOk9FcS9hkChqn9uvQsLRRAnkPmBBMdnbWf6+uuebKIxngUxo36jarBflC7Jyrhjd4K7+VqdbgT0t1RcORC5TXzv3aJqZ9Lw7zX8mOTjpIqWu7798d1Ic85v/vigo4t+pO9gbPOzMXepRw4myPsT3UfHyiuzzOTNvtXPXUjBNhjyE301H0ycGnPqPU" Mar 25 06:01:37 katarynka go-librespot[29332]: time="2026-03-25T06:01:37+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:01:37 katarynka volumio[29097]: info: Starting Shairport Sync Mar 25 06:01:37 katarynka volumio[29097]: info: Starting Shairport Sync Mar 25 06:01:37 katarynka go-librespot[29332]: time="2026-03-25T06:01:37+01:00" level=debug msg="completed keyexchange" Mar 25 06:01:37 katarynka go-librespot[29332]: time="2026-03-25T06:01:37+01:00" level=debug msg="completed challenge" Mar 25 06:01:37 katarynka volumio[29097]: info: Starting Shairport Sync Mar 25 06:01:37 katarynka go-librespot[29332]: time="2026-03-25T06:01:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:01:37 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:37 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:37 katarynka sudo[29353]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 25 06:01:37 katarynka sudo[29352]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 25 06:01:37 katarynka sudo[29353]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:37 katarynka sudo[29352]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:37 katarynka sudo[29355]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 25 06:01:37 katarynka sudo[29355]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:37 katarynka sudo[29357]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 25 06:01:37 katarynka sudo[29357]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:37 katarynka systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 25 06:01:37 katarynka systemd[1]: shairport-sync.service: Deactivated successfully. Mar 25 06:01:37 katarynka systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 25 06:01:37 katarynka systemd[1]: shairport-sync.service: Consumed 6.514s CPU time. Mar 25 06:01:37 katarynka volumio[29097]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 25 06:01:37 katarynka systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 25 06:01:37 katarynka sudo[29355]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:37 katarynka sudo[29352]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:37 katarynka sudo[29353]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:38 katarynka volumio[29097]: info: CoreCommandRouter::volumioGetState Mar 25 06:01:38 katarynka sudo[29357]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:38 katarynka volumio[29097]: info: CorePlayQueue::getTrack 0 Mar 25 06:01:38 katarynka volumio[29097]: info: Shairport-Sync Started Mar 25 06:01:38 katarynka volumio[29097]: Error adding Membership: Error: addMembership EINVAL Mar 25 06:01:38 katarynka volumio[29097]: info: Shairport-Sync Started Mar 25 06:01:38 katarynka volumio[29097]: info: Upmpdcli Daemon Started Mar 25 06:01:38 katarynka volumio[29097]: info: Shairport-Sync Started Mar 25 06:01:40 katarynka volumio[29097]: info: go-librespot daemon successfully initialized Mar 25 06:01:40 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 25 06:01:40 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:40 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:40 katarynka go-librespot[29397]: go-librespot daemon starting... Mar 25 06:01:40 katarynka go-librespot[29398]: time="2026-03-25T06:01:40+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:40 katarynka go-librespot[29398]: time="2026-03-25T06:01:40+01:00" level=debug msg="app state loaded" Mar 25 06:01:40 katarynka go-librespot[29398]: time="2026-03-25T06:01:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:01:40 katarynka mpd[29293]: 2026-03-25T06:01:40 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 25 06:01:41 katarynka systemd[1]: Started mpd.service - Music Player Daemon. Mar 25 06:01:41 katarynka sudo[29264]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:41 katarynka sudo[29254]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:41 katarynka volumio[29097]: info: Completed starting Core Plugins Mar 25 06:01:41 katarynka volumio[29097]: info: ------------------------------------------- Mar 25 06:01:41 katarynka volumio[29097]: info: ----- MyVolumio plugins startup ---- Mar 25 06:01:41 katarynka volumio[29097]: info: ------------------------------------------- Mar 25 06:01:41 katarynka volumio[29097]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 25 06:01:41 katarynka go-librespot[29398]: time="2026-03-25T06:01:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:01:41 katarynka go-librespot[29398]: time="2026-03-25T06:01:41+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:01:41 katarynka go-librespot[29398]: time="2026-03-25T06:01:41+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:01:41 katarynka go-librespot[29398]: time="2026-03-25T06:01:41+01:00" level=info msg="zeroconf server listening on port 46703" Mar 25 06:01:41 katarynka volumio[29097]: error: MPD error: The expression evaluated to a falsy value: Mar 25 06:01:41 katarynka volumio[29097]: assert.ok(self.idling) Mar 25 06:01:41 katarynka volumio[29097]: error: The expression evaluated to a falsy value: Mar 25 06:01:41 katarynka volumio[29097]: assert.ok(self.idling) Mar 25 06:01:41 katarynka volumio[29097]: info: MPD running with PID29293 Mar 25 06:01:41 katarynka volumio[29097]: ,establishing connection Mar 25 06:01:41 katarynka volumio[29097]: error: updateQueue error: null Mar 25 06:01:41 katarynka volumio[29097]: error: updateQueue error: null Mar 25 06:01:41 katarynka go-librespot[29398]: time="2026-03-25T06:01:41+01:00" level=debug msg="obtained new client token: AABQtdCRkQ8aOFlJUteU5zRpEdTe3V5KDRVgMeQO228k1QchNKPYrWo5HITHq+NBq21IySAPXJ7dduRhF+i5Bza8Jedcxz6awd0vgzbcbn/o19qT96ON5yEWaMRPZaOZihA+uC3F2G464tK5dOP851F8QHRIyk+PrqH+ThRTgGQApnCA6BWvpLcVPSJ2OGcxpPhxQVehbdfwHn1Nn2ho6amSTIJb7/E9rb7d2hZmQj7DKR2Za5o0v1U+uPE=" Mar 25 06:01:41 katarynka go-librespot[29398]: time="2026-03-25T06:01:41+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:01:41 katarynka go-librespot[29398]: time="2026-03-25T06:01:41+01:00" level=debug msg="completed keyexchange" Mar 25 06:01:41 katarynka go-librespot[29398]: time="2026-03-25T06:01:41+01:00" level=debug msg="completed challenge" Mar 25 06:01:41 katarynka go-librespot[29398]: time="2026-03-25T06:01:41+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:01:41 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:41 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:43 katarynka volumio[29097]: info: Initializing connection to go-librespot Websocket Mar 25 06:01:43 katarynka volumio[29097]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 25 06:01:44 katarynka sudo[29412]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Mar 25 06:01:44 katarynka sudo[29412]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:44 katarynka sudo[29414]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Mar 25 06:01:44 katarynka sudo[29414]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:44 katarynka systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Mar 25 06:01:44 katarynka systemd[1]: mpd_monitor.service: Deactivated successfully. Mar 25 06:01:44 katarynka systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Mar 25 06:01:44 katarynka systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Mar 25 06:01:44 katarynka sudo[29412]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:44 katarynka sudo[29414]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:44 katarynka mpd_monitor.sh[29431]: MPD Monitor Service: Starting MPD Monitor Service Mar 25 06:01:44 katarynka volumio[29097]: info: Successfully started MPD Monitor Mar 25 06:01:44 katarynka volumio[29097]: info: Successfully started MPD Monitor Mar 25 06:01:44 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 25 06:01:44 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:44 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:44 katarynka go-librespot[29435]: go-librespot daemon starting... Mar 25 06:01:44 katarynka go-librespot[29436]: time="2026-03-25T06:01:44+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:44 katarynka go-librespot[29436]: time="2026-03-25T06:01:44+01:00" level=debug msg="app state loaded" Mar 25 06:01:44 katarynka go-librespot[29436]: time="2026-03-25T06:01:44+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:01:45 katarynka go-librespot[29436]: time="2026-03-25T06:01:45+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:01:45 katarynka go-librespot[29436]: time="2026-03-25T06:01:45+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:01:45 katarynka go-librespot[29436]: time="2026-03-25T06:01:45+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:01:45 katarynka go-librespot[29436]: time="2026-03-25T06:01:45+01:00" level=info msg="zeroconf server listening on port 46649" Mar 25 06:01:45 katarynka go-librespot[29436]: time="2026-03-25T06:01:45+01:00" level=debug msg="obtained new client token: AACB6KpoUDlXehZXEGAmDA82XTWysp0lFpCyE4yyDi4imSTBIgyOK1ZambixSmG89l7b2Rdg4DnRmBnww2pSo3TCpdb6BxAYM7z1qIdh3BNU71DNey099FT9lM5FIIDs2T5drIjv0ztxoyq+PWMkOC+OooZvDWJDzmZS5p/xHC5GJymurAaOk9ZrSb960PjrbQgAjbqE1D4Z7T3i+5Q+NjEUn8Qe/0QJddZZzluWzNDgloTkHqddt3ge" Mar 25 06:01:45 katarynka go-librespot[29436]: time="2026-03-25T06:01:45+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 25 06:01:45 katarynka go-librespot[29436]: time="2026-03-25T06:01:45+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 25 06:01:45 katarynka go-librespot[29436]: time="2026-03-25T06:01:45+01:00" level=debug msg="completed keyexchange" Mar 25 06:01:45 katarynka go-librespot[29436]: time="2026-03-25T06:01:45+01:00" level=debug msg="completed challenge" Mar 25 06:01:45 katarynka go-librespot[29436]: time="2026-03-25T06:01:45+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:01:45 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:45 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:46 katarynka volumio[29097]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 25 06:01:46 katarynka volumio[29097]: info: Initializing connection to go-librespot Websocket Mar 25 06:01:46 katarynka volumio[29097]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 25 06:01:48 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Mar 25 06:01:48 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:48 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:48 katarynka go-librespot[29443]: go-librespot daemon starting... Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=debug msg="app state loaded" Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:01:49 katarynka volumio[29097]: info: Initializing connection to go-librespot Websocket Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=debug msg="new websocket client" Mar 25 06:01:49 katarynka volumio[29097]: info: Connection to go-librespot Websocket established Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=info msg="zeroconf server listening on port 34493" Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=debug msg="obtained new client token: AAC5wAJBm6/D3POupD9GuHK+/JZNUqKLFXbh0oI1sfXA8hgr3MDjx8XToaOMYMuW0JJOUXj9CHE8sNTxF/Y2eVGr74D44b02iTxyM8WBUJJOCfDSzX80NpJAPb1tZHR0/GI6L7fJFoUX2Pd0M9S7XojrgGJny6SoKnhnQA4Ob4wzRtfDqDlccC3j+2FW2d/bMPpOFJJlsmd70a0K+ln3+9YfiLD9UEqrmf7PjDesuFwLYepWaJN6AJqws+U=" Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 25 06:01:49 katarynka volumio[29097]: info: Adding plugin bluetooth to MyMusic Plugins Mar 25 06:01:49 katarynka volumio[29097]: info: Adding plugin multiroom to MyMusic Plugins Mar 25 06:01:49 katarynka volumio[29097]: info: Adding plugin metavolumio to MyMusic Plugins Mar 25 06:01:49 katarynka volumio[29097]: info: Adding plugin cd_controller to MyMusic Plugins Mar 25 06:01:49 katarynka volumio[29097]: info: Adding plugin qobuzconnect to MyMusic Plugins Mar 25 06:01:49 katarynka volumio[29097]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 25 06:01:49 katarynka volumio[29097]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 25 06:01:49 katarynka volumio[29097]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=debug msg="completed keyexchange" Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=debug msg="completed challenge" Mar 25 06:01:49 katarynka go-librespot[29444]: time="2026-03-25T06:01:49+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:01:49 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:49 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:51 katarynka volumio[29097]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 25 06:01:51 katarynka volumio[29097]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 25 06:01:51 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:01:51 katarynka volumio[29097]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:01:51 katarynka volumio[29097]: info: Starting MyVolumio Remote Streaming Endpoints Mar 25 06:01:51 katarynka volumio[29097]: info: MyVolumio login type: Token Mar 25 06:01:51 katarynka volumio[29097]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 25 06:01:51 katarynka volumio[29097]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 25 06:01:52 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Mar 25 06:01:52 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:52 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:52 katarynka go-librespot[29451]: go-librespot daemon starting... Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=debug msg="app state loaded" Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=info msg="zeroconf server listening on port 45733" Mar 25 06:01:53 katarynka volumio[29097]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 25 06:01:53 katarynka volumio[29097]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 25 06:01:53 katarynka volumio[29097]: info: Streaming services startup Mar 25 06:01:53 katarynka volumio[29097]: info: Starting Streaming Daemon Mar 25 06:01:53 katarynka sudo[29461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 25 06:01:53 katarynka sudo[29461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:53 katarynka volumio[29097]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=debug msg="obtained new client token: AACjGPKZYa9Xtzbo6FLhQlg0iXYco9q8TJB1ehqFBe3m3zMoFWfDc2j0+xePSARWyces7Um86nvz58cu/dG4WxbKbBMpPE4u1vWELlZHbsr1tz+yIDI0QS05dOvfnE1X65d6eanVHbPff6bLnbTyKPLOpWaJuDiFMjmDVTdyxQw0lIVJBZbl02QlY/45/QQWx27ierjNUSjNF5gnqhnHDr6lI9tjCFeIIFXeh5Dk19SG/YiVwhnvhkaTVxI=" Mar 25 06:01:53 katarynka sudo[29461]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 25 06:01:53 katarynka volumio[29097]: info: Getting Spotify volume Mar 25 06:01:53 katarynka volumio[29097]: info: Connection to go-librespot Websocket closed Mar 25 06:01:53 katarynka volumio[29097]: error: Cannot start Volumio Streaming Daemon Mar 25 06:01:53 katarynka volumio[29097]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 25 06:01:53 katarynka volumio[29097]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=debug msg="completed keyexchange" Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=debug msg="completed challenge" Mar 25 06:01:53 katarynka volumio[29097]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 25 06:01:53 katarynka go-librespot[29452]: time="2026-03-25T06:01:53+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:01:53 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:53 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:54 katarynka volumio[29097]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 25 06:01:54 katarynka volumio[29097]: Error: socket hang up Mar 25 06:01:54 katarynka volumio[29097]: at connResetException (node:internal/errors:720:14) Mar 25 06:01:54 katarynka volumio[29097]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 25 06:01:54 katarynka volumio[29097]: at Socket.emit (node:events:526:35) Mar 25 06:01:54 katarynka volumio[29097]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 25 06:01:54 katarynka volumio[29097]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 25 06:01:54 katarynka volumio[29097]: code: 'ECONNRESET', Mar 25 06:01:54 katarynka volumio[29097]: response: undefined Mar 25 06:01:54 katarynka volumio[29097]: } Mar 25 06:01:54 katarynka volumio[29097]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 25 06:01:55 katarynka sudo[29497]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-25 06:00' Mar 25 06:01:55 katarynka sudo[29497]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:01:55 katarynka sudo[29497]: pam_unix(sudo:session): session closed for user root Mar 25 06:01:55 katarynka volumio-remote-updater[622]: [2026-03-25 06:01:55] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 25 06:01:55 katarynka systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:55 katarynka volumio-remote-updater[622]: [2026-03-25 06:01:55] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 25 06:01:55 katarynka systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 25 06:01:55 katarynka systemd[1]: volumio.service: Consumed 49.034s CPU time. Mar 25 06:01:55 katarynka systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 25 06:01:56 katarynka systemd[1]: dynamicswap.service: Deactivated successfully. Mar 25 06:01:56 katarynka systemd[1]: volumio.service: Scheduled restart job, restart counter is at 25999. Mar 25 06:01:56 katarynka systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 25 06:01:56 katarynka systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 25 06:01:56 katarynka systemd[1]: volumio.service: Consumed 49.034s CPU time. Mar 25 06:01:56 katarynka systemd[1]: Started volumio.service - Volumio Backend Module. Mar 25 06:01:56 katarynka systemd[1]: dynamicswap.service: Deactivated successfully. Mar 25 06:01:57 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Mar 25 06:01:57 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:57 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:01:57 katarynka go-librespot[29529]: go-librespot daemon starting... Mar 25 06:01:57 katarynka go-librespot[29530]: time="2026-03-25T06:01:57+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:01:57 katarynka go-librespot[29530]: time="2026-03-25T06:01:57+01:00" level=debug msg="app state loaded" Mar 25 06:01:57 katarynka go-librespot[29530]: time="2026-03-25T06:01:57+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:01:57 katarynka go-librespot[29530]: time="2026-03-25T06:01:57+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 25 06:01:57 katarynka go-librespot[29530]: time="2026-03-25T06:01:57+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 25 06:01:57 katarynka go-librespot[29530]: time="2026-03-25T06:01:57+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 25 06:01:57 katarynka go-librespot[29530]: time="2026-03-25T06:01:57+01:00" level=info msg="zeroconf server listening on port 36199" Mar 25 06:01:57 katarynka go-librespot[29530]: time="2026-03-25T06:01:57+01:00" level=debug msg="obtained new client token: AACGd5lnj9PZvsXMlymkmDVHBA0YHVnOSeJFWDg9GGKU6maOrFYZbXOVM0DLd6l5iZ/7gB2P1IpSM5HqEcK887Z9xgkXQj4XBW7wglqj4jauVdXWSxPyof0ppzdokXDkAurxjnetYtTXjcSyAql7EFAhhtRJfHbNSMTAJi3lRK0DJ+Y9kNR3AbMDCI23yRt/eYLiNgGt/u5Xgf/FWJrOQQUBU1FWIdke5D1fT0WG0KhijKyCOjXSpxXnUco=" Mar 25 06:01:57 katarynka go-librespot[29530]: time="2026-03-25T06:01:57+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:01:58 katarynka go-librespot[29530]: time="2026-03-25T06:01:58+01:00" level=debug msg="completed keyexchange" Mar 25 06:01:58 katarynka go-librespot[29530]: time="2026-03-25T06:01:58+01:00" level=debug msg="completed challenge" Mar 25 06:01:58 katarynka go-librespot[29530]: time="2026-03-25T06:01:58+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:01:58 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:01:58 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:01:59 katarynka volumio[29514]: info: ------------------------------------------- Mar 25 06:01:59 katarynka volumio[29514]: info: ----- Volumio3 ---- Mar 25 06:01:59 katarynka volumio[29514]: info: ------------------------------------------- Mar 25 06:01:59 katarynka volumio[29514]: info: ----- System startup ---- Mar 25 06:01:59 katarynka volumio[29514]: info: ------------------------------------------- Mar 25 06:02:00 katarynka volumio-remote-updater[622]: [2026-03-25 06:02:00] [connect] Successful connection Mar 25 06:02:01 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Mar 25 06:02:01 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:01 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:01 katarynka go-librespot[29544]: go-librespot daemon starting... Mar 25 06:02:01 katarynka go-librespot[29545]: time="2026-03-25T06:02:01+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:02:01 katarynka go-librespot[29545]: time="2026-03-25T06:02:01+01:00" level=debug msg="app state loaded" Mar 25 06:02:01 katarynka go-librespot[29545]: time="2026-03-25T06:02:01+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:02:01 katarynka volumio[29514]: info: MYVOLUMIO Environment detected Mar 25 06:02:01 katarynka volumio[29514]: info: Plugin folders cleanup Mar 25 06:02:01 katarynka volumio[29514]: info: Scanning into folder /volumio/app/plugins/ Mar 25 06:02:01 katarynka volumio[29514]: info: Scanning category audio_interface Mar 25 06:02:01 katarynka volumio[29514]: info: Scanning category miscellanea Mar 25 06:02:01 katarynka volumio[29514]: info: Scanning category music_service Mar 25 06:02:01 katarynka volumio[29514]: info: Scanning category plugins.json Mar 25 06:02:01 katarynka volumio[29514]: info: Scanning category system_controller Mar 25 06:02:01 katarynka volumio[29514]: info: Scanning category user_interface Mar 25 06:02:01 katarynka volumio[29514]: info: Scanning into folder /data/plugins/ Mar 25 06:02:01 katarynka volumio[29514]: info: Scanning category music_service Mar 25 06:02:01 katarynka volumio[29514]: info: Plugin folders cleanup completed Mar 25 06:02:01 katarynka volumio[29514]: info: ------------------------------------------- Mar 25 06:02:01 katarynka volumio[29514]: info: ----- Core plugins startup ---- Mar 25 06:02:01 katarynka volumio[29514]: info: ------------------------------------------- Mar 25 06:02:01 katarynka volumio[29514]: info: Loading plugins from folder /volumio/app/plugins/ Mar 25 06:02:01 katarynka volumio[29514]: info: Adding plugin upnp to MyMusic Plugins Mar 25 06:02:01 katarynka volumio[29514]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 25 06:02:01 katarynka volumio[29514]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 25 06:02:01 katarynka volumio[29514]: info: Loading plugins from folder /data/plugins/ Mar 25 06:02:01 katarynka volumio[29514]: info: Loading plugin "system"... Mar 25 06:02:01 katarynka volumio[29514]: info: Loading plugin "appearance"... Mar 25 06:02:01 katarynka go-librespot[29545]: time="2026-03-25T06:02:01+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 25 06:02:01 katarynka go-librespot[29545]: time="2026-03-25T06:02:01+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 25 06:02:01 katarynka go-librespot[29545]: time="2026-03-25T06:02:01+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 25 06:02:01 katarynka go-librespot[29545]: time="2026-03-25T06:02:01+01:00" level=info msg="zeroconf server listening on port 34973" Mar 25 06:02:01 katarynka go-librespot[29545]: time="2026-03-25T06:02:01+01:00" level=debug msg="obtained new client token: AAAVAPacVg1QdKg3QL4qtHvTG8tI71Q9abzxgdJbrozB4sPMibeyfkOsAzn+zRcJ/mc3/cO8O8HntgTVHQnW4DyGs0OC2zBANP5587gw9/hPKmAMRWyAwjKNlaLCzsfZ41W5AIKiWPSDFtIMc72NzmkFQR3lRzsVuXCV/+Eo146SrS0GgLixB6zrLYMVc11uAb6yeMz7aX4hv0lUeC0GyyfUae6aeJE1y8Lo5KzjHAlXExTUWmyYT35UP6A=" Mar 25 06:02:01 katarynka go-librespot[29545]: time="2026-03-25T06:02:01+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 25 06:02:01 katarynka go-librespot[29545]: time="2026-03-25T06:02:01+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 25 06:02:02 katarynka go-librespot[29545]: time="2026-03-25T06:02:02+01:00" level=debug msg="completed keyexchange" Mar 25 06:02:02 katarynka go-librespot[29545]: time="2026-03-25T06:02:02+01:00" level=debug msg="completed challenge" Mar 25 06:02:02 katarynka go-librespot[29545]: time="2026-03-25T06:02:02+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:02:02 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:02:02 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:02:03 katarynka volumio[29514]: info: Loading plugin "network"... Mar 25 06:02:03 katarynka volumio[29514]: info: Refreshing Cached IP Addresses Mar 25 06:02:03 katarynka sudo[29559]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 25 06:02:03 katarynka sudo[29559]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:03 katarynka sudo[29561]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 25 06:02:03 katarynka sudo[29561]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:03 katarynka sudo[29559]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:03 katarynka sudo[29561]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:03 katarynka volumio[29514]: info: Loading plugin "services"... Mar 25 06:02:03 katarynka volumio[29514]: info: Loading plugin "alsa_controller"... Mar 25 06:02:03 katarynka sudo[29569]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 25 06:02:03 katarynka sudo[29569]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:03 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 25 06:02:03 katarynka volumio[29514]: info: Loading plugin "wizard"... Mar 25 06:02:03 katarynka volumio[29514]: info: Loading plugin "networkfs"... Mar 25 06:02:04 katarynka volumio[29514]: info: Starting Udev Watcher for removable devices Mar 25 06:02:04 katarynka volumio[29514]: info: Ignoring mount for partition: boot Mar 25 06:02:04 katarynka volumio[29514]: info: Ignoring mount for partition: volumio Mar 25 06:02:04 katarynka volumio[29514]: info: Ignoring mount for partition: volumio_data Mar 25 06:02:04 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 25 06:02:04 katarynka volumio[29514]: info: Loading plugin "volumio_command_line_client"... Mar 25 06:02:04 katarynka volumio[29514]: info: Loading plugin "upnp"... Mar 25 06:02:04 katarynka volumio[29514]: info: [1774414924109] Starting Upmpd Daemon Mar 25 06:02:04 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 25 06:02:04 katarynka volumio[29514]: info: Loading plugin "my_music"... Mar 25 06:02:04 katarynka volumio[29514]: info: Loading plugin "mpd"... Mar 25 06:02:04 katarynka sudo[29569]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:04 katarynka volumio[29514]: info: Loading plugin "upnp_browser"... Mar 25 06:02:05 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Mar 25 06:02:05 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:05 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:05 katarynka go-librespot[29595]: go-librespot daemon starting... Mar 25 06:02:05 katarynka go-librespot[29596]: time="2026-03-25T06:02:05+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:02:05 katarynka go-librespot[29596]: time="2026-03-25T06:02:05+01:00" level=debug msg="app state loaded" Mar 25 06:02:05 katarynka go-librespot[29596]: time="2026-03-25T06:02:05+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:02:05 katarynka go-librespot[29596]: time="2026-03-25T06:02:05+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 25 06:02:05 katarynka go-librespot[29596]: time="2026-03-25T06:02:05+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 25 06:02:05 katarynka go-librespot[29596]: time="2026-03-25T06:02:05+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 25 06:02:05 katarynka go-librespot[29596]: time="2026-03-25T06:02:05+01:00" level=info msg="zeroconf server listening on port 44017" Mar 25 06:02:05 katarynka go-librespot[29596]: time="2026-03-25T06:02:05+01:00" level=debug msg="obtained new client token: AAA5uiFeSZZcwn9mrK6+f2LaEtH/olVYGjH2Mi4cAhCUD/X/XyTT7diEZhtWiCrglvfIww0JiUXV5v6/QYvI33OvLG3GLmjCyzP7TxJCklcsxQMq9cFsTU7jch0oVZ5h8kcWTDdQHx1tgo113fCTUS5BfdDg7fXVtTcxF8Xd9fIptObOshG0p1UXSnelUdujA355cO2CZm4cCP34aTMIYTSuDwvEUis4CVcWEg/ViFCLQjIsyD2erL0uqkU=" Mar 25 06:02:06 katarynka go-librespot[29596]: time="2026-03-25T06:02:06+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:02:06 katarynka go-librespot[29596]: time="2026-03-25T06:02:06+01:00" level=debug msg="completed keyexchange" Mar 25 06:02:06 katarynka go-librespot[29596]: time="2026-03-25T06:02:06+01:00" level=debug msg="completed challenge" Mar 25 06:02:06 katarynka go-librespot[29596]: time="2026-03-25T06:02:06+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:02:06 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:02:06 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:02:07 katarynka volumio[29514]: info: Starting UPNP Browser Mar 25 06:02:07 katarynka volumio[29514]: info: Loading plugin "alarm-clock"... Mar 25 06:02:08 katarynka volumio[29514]: info: Loading plugin "airplay_emulation"... Mar 25 06:02:08 katarynka volumio[29514]: info: Starting Shairport Sync Mar 25 06:02:08 katarynka volumio[29514]: info: Loading plugin "last_100"... Mar 25 06:02:08 katarynka volumio[29514]: info: Loading plugin "webradio"... Mar 25 06:02:08 katarynka volumio[29514]: info: Loading plugin "i2s_dacs"... Mar 25 06:02:08 katarynka volumio[29514]: info: Loading plugin "volumiodiscovery"... Mar 25 06:02:08 katarynka volumio[29514]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 25 06:02:08 katarynka volumio[29514]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 25 06:02:08 katarynka volumio[29514]: *** WARNING *** For more information see Mar 25 06:02:08 katarynka volumio[29514]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 25 06:02:08 katarynka volumio[29514]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 25 06:02:08 katarynka volumio[29514]: *** WARNING *** For more information see Mar 25 06:02:08 katarynka node[29514]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 25 06:02:08 katarynka node[29514]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 25 06:02:08 katarynka node[29514]: *** WARNING *** For more information see Mar 25 06:02:08 katarynka node[29514]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 25 06:02:08 katarynka node[29514]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 25 06:02:08 katarynka node[29514]: *** WARNING *** For more information see Mar 25 06:02:08 katarynka volumio[29514]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 25 06:02:08 katarynka volumio[29514]: info: Discovery: Started advertising with name: katarynka Mar 25 06:02:08 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 25 06:02:08 katarynka volumio[29514]: info: Loading plugin "spop"... Mar 25 06:02:09 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Mar 25 06:02:09 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:09 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:09 katarynka go-librespot[29605]: go-librespot daemon starting... Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=debug msg="app state loaded" Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=info msg="zeroconf server listening on port 33501" Mar 25 06:02:10 katarynka volumio[29514]: info: Loading plugin "outputs"... Mar 25 06:02:10 katarynka volumio[29514]: info: Loading plugin "albumart"... Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=debug msg="obtained new client token: AABzXio7KmEqQ+8tcXeoL5rh7IBhnaOXCpgE00uZx3xKo2oRJ8QiPCkVpL85knlz2sC0ibF3y2Rs70VmTsBOAK0k5GR4LvajgESMSHIfKvVfryXylrQjGH591UHeqLwtJkipFvqcAQypuJcGsNkshwpEKfsj0tBXJLwBrOh1kuMl7f9jW7uI0bekmhjBRJVtC9WTazMpLhpjTeDFqrqnJXnwwWIZ0PDC49ekEskeZW/Sb81nfpCykG41x/M=" Mar 25 06:02:10 katarynka volumio[29514]: info: Plugin example_plugin is not enabled Mar 25 06:02:10 katarynka volumio[29514]: info: Loading plugin "inputs"... Mar 25 06:02:10 katarynka volumio[29514]: info: Loading plugin "updater_comm"... Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=debug msg="completed keyexchange" Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=debug msg="completed challenge" Mar 25 06:02:10 katarynka go-librespot[29606]: time="2026-03-25T06:02:10+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:02:10 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:02:10 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:02:11 katarynka volumio[29514]: info: Plugin mpdemulation is not enabled Mar 25 06:02:11 katarynka volumio[29514]: info: Loading plugin "rest_api"... Mar 25 06:02:11 katarynka volumio[29514]: info: Loading plugin "websocket"... Mar 25 06:02:11 katarynka volumio[29514]: info: Starting Socket.io Server version 1.7.4 Mar 25 06:02:11 katarynka volumio[29514]: info: Loading i18n strings for locale pl Mar 25 06:02:11 katarynka volumio[29514]: Updating browse sources language Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::initPlayerControls Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: Express server listening on port 3000 Mar 25 06:02:11 katarynka volumio[29514]: [Metrics] WebUI: 12s 573.10ms Mar 25 06:02:11 katarynka volumio[29514]: info: CoreStateMachine::resetVolumioState Mar 25 06:02:11 katarynka volumio[29514]: info: CoreStateMachine::getcurrentVolume Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::volumioRetrievevolume Mar 25 06:02:11 katarynka volumio[29514]: info: Cannot read play queue from file Mar 25 06:02:11 katarynka volumio[29514]: info: Volumio Network Manager: Network status updated: 2 Mar 25 06:02:11 katarynka volumio[29613]: Forking 3 albumart workers Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:11 katarynka volumio[29514]: info: CoreStateMachine::setRepeat null single undefined Mar 25 06:02:11 katarynka volumio[29514]: info: CoreStateMachine::pushState Mar 25 06:02:11 katarynka volumio[29514]: info: CorePlayQueue::getTrack 0 Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::volumioPushState Mar 25 06:02:11 katarynka volumio[29514]: info: CoreStateMachine::setRandom null Mar 25 06:02:11 katarynka volumio[29514]: info: CoreStateMachine::pushState Mar 25 06:02:11 katarynka volumio[29514]: info: CorePlayQueue::getTrack 0 Mar 25 06:02:11 katarynka volumio[29514]: info: CoreCommandRouter::volumioPushState Mar 25 06:02:11 katarynka volumio[29514]: info: Setting Device type: Raspberry PI Mar 25 06:02:11 katarynka volumio[29514]: info: Completed loading Core Plugins Mar 25 06:02:11 katarynka volumio[29514]: info: Preparing to generate the ALSA configuration file Mar 25 06:02:12 katarynka volumio[29514]: info: VolumeController:: Volume=96 Mute =false Mar 25 06:02:12 katarynka volumio[29514]: info: CoreStateMachine::pushState Mar 25 06:02:12 katarynka volumio[29514]: info: CorePlayQueue::getTrack 0 Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::volumioPushState Mar 25 06:02:12 katarynka volumio[29514]: info: CoreStateMachine::updateTrackBlock Mar 25 06:02:12 katarynka volumio[29514]: info: CorePlayQueue::getTrackBlock Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::volumioRetrievevolume Mar 25 06:02:12 katarynka volumio[29514]: info: Asound.conf file unchanged, so no further update is needed Mar 25 06:02:12 katarynka volumio[29514]: info: Output device has changed, restarting MPD Mar 25 06:02:12 katarynka volumio[29514]: info: Output device has changed, restarting Shairport Sync Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:12 katarynka volumio[29514]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 25 06:02:12 katarynka volumio[29514]: info: ___________ START PLUGINS ___________ Mar 25 06:02:12 katarynka sudo[29667]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 25 06:02:12 katarynka sudo[29667]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:12 katarynka volumio[29514]: info: ControllerMpd::onStart: Initializing MPD Mar 25 06:02:12 katarynka volumio[29514]: info: Creating MPD Configuration file Mar 25 06:02:12 katarynka sudo[29667]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:12 katarynka sudo[29671]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 25 06:02:12 katarynka sudo[29671]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 25 06:02:12 katarynka volumio[29514]: info: [1774414932468] CoreMusicLibrary::Adding element Serwery Mediów Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 25 06:02:12 katarynka volumio[29514]: info: UPNP Browser: Client initialized successfully Mar 25 06:02:12 katarynka sudo[29676]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 25 06:02:12 katarynka sudo[29676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:12 katarynka sudo[29676]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:12 katarynka sudo[29678]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 25 06:02:12 katarynka sudo[29678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:12 katarynka systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 25 06:02:12 katarynka volumio[29514]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:12 katarynka volumio[29514]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 25 06:02:12 katarynka systemd[1]: mpd.service: Deactivated successfully. Mar 25 06:02:12 katarynka systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 25 06:02:12 katarynka systemd[1]: mpd.service: Consumed 7.793s CPU time. Mar 25 06:02:12 katarynka systemd[1]: mpd.socket: Deactivated successfully. Mar 25 06:02:12 katarynka systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 25 06:02:12 katarynka systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 25 06:02:12 katarynka volumio[29514]: info: [1774414932773] CoreMusicLibrary::Adding element Last_100 Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 25 06:02:12 katarynka volumio[29514]: info: [1774414932783] CoreMusicLibrary::Adding element Webradio Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 25 06:02:12 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 25 06:02:12 katarynka volumio[29514]: info: Initializing BBC Radios Mar 25 06:02:12 katarynka systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 25 06:02:12 katarynka systemd[1]: Starting mpd.service - Music Player Daemon... Mar 25 06:02:13 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 25 06:02:13 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:13 katarynka volumio[29514]: info: Creating Spotify config file Mar 25 06:02:13 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:13 katarynka volumio-remote-updater[622]: [2026-03-25 06:02:13] [connect] Successful connection Mar 25 06:02:13 katarynka sudo[29696]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 25 06:02:13 katarynka sudo[29696]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 25 06:02:13 katarynka sudo[29696]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:14 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Mar 25 06:02:14 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:14 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:14 katarynka go-librespot[29722]: go-librespot daemon starting... Mar 25 06:02:14 katarynka volumio[29514]: info: Volumio Calling Home Mar 25 06:02:14 katarynka go-librespot[29723]: time="2026-03-25T06:02:14+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:02:15 katarynka go-librespot[29723]: time="2026-03-25T06:02:15+01:00" level=info msg="zeroconf server listening on port 32889" Mar 25 06:02:15 katarynka volumio[29514]: info: Discovery: adding 4d616d77-6a8c-4da2-85a4-840d70f98e51 Mar 25 06:02:15 katarynka volumio[29514]: info: Discovery: Found device katarynka Mar 25 06:02:15 katarynka volumio[29514]: info: CoreCommandRouter::volumioGetState Mar 25 06:02:15 katarynka volumio[29514]: info: CorePlayQueue::getTrack 0 Mar 25 06:02:15 katarynka volumio[29631]: Starting albumart workers Mar 25 06:02:15 katarynka volumio[29633]: Starting albumart workers Mar 25 06:02:15 katarynka volumio[29514]: info: Discovery: this is already registered, 4d616d77-6a8c-4da2-85a4-840d70f98e51 Mar 25 06:02:15 katarynka volumio[29634]: Starting albumart workers Mar 25 06:02:15 katarynka volumio[29514]: info: Discovery: Found device katarynka Mar 25 06:02:15 katarynka volumio[29514]: info: CoreCommandRouter::volumioGetState Mar 25 06:02:15 katarynka volumio[29514]: info: CorePlayQueue::getTrack 0 Mar 25 06:02:15 katarynka sudo[29736]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 25 06:02:15 katarynka sudo[29736]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:15 katarynka sudo[29736]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:15 katarynka sudo[29737]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 25 06:02:15 katarynka sudo[29737]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:15 katarynka volumio[29514]: info: MPD Permissions set Mar 25 06:02:15 katarynka sudo[29737]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:16 katarynka volumio[29514]: info: MPD Permissions set Mar 25 06:02:16 katarynka volumio[29514]: info: VolumeController:: Volume=96 Mute =false Mar 25 06:02:16 katarynka volumio[29514]: info: CoreStateMachine::pushState Mar 25 06:02:16 katarynka volumio[29514]: info: CorePlayQueue::getTrack 0 Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::volumioPushState Mar 25 06:02:16 katarynka volumio-remote-updater[622]: [2026-03-25 06:02:16] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774414933 101 Mar 25 06:02:16 katarynka volumio[29514]: 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: 1 Mar 25 06:02:16 katarynka volumio[29514]: info: Volumio called home Mar 25 06:02:16 katarynka volumio[29514]: info: Spotify config file written Mar 25 06:02:16 katarynka sudo[29741]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 25 06:02:16 katarynka sudo[29741]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:16 katarynka systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 25 06:02:16 katarynka systemd[1]: go-librespot-daemon.service: Killing process 29733 (go-librespot) with signal SIGKILL. Mar 25 06:02:16 katarynka systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 25 06:02:16 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:16 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:16 katarynka volumio[29514]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Mar 25 06:02:16 katarynka go-librespot[29743]: go-librespot daemon starting... Mar 25 06:02:16 katarynka sudo[29741]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka go-librespot[29745]: time="2026-03-25T06:02:16+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:02:16 katarynka go-librespot[29745]: time="2026-03-25T06:02:16+01:00" level=debug msg="app state loaded" Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka go-librespot[29745]: time="2026-03-25T06:02:16+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:16 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:17 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:17 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 06:02:17 katarynka volumio[29514]: info: No need to fix Spotify hosts Mar 25 06:02:17 katarynka go-librespot[29745]: time="2026-03-25T06:02:17+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:02:17 katarynka go-librespot[29745]: time="2026-03-25T06:02:17+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:02:17 katarynka go-librespot[29745]: time="2026-03-25T06:02:17+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:02:17 katarynka go-librespot[29745]: time="2026-03-25T06:02:17+01:00" level=info msg="zeroconf server listening on port 45601" Mar 25 06:02:17 katarynka go-librespot[29745]: time="2026-03-25T06:02:17+01:00" level=debug msg="obtained new client token: AABy8JXCrvwM48KFLbi/cNgSJe7htuM2W930LiM0PWwRzcMAY5XqU9O8S6/BsnTGI2m98To1pcwgpixWPcixCoeNXbx0tQwBtnZDAKicgRZw42SlQanl6fgSbgGgaa17sbc5cSQW1WFAN8U9BCVV505m+0lpBARZ2iZs8oReFf0IrNwI2Q6pnBi45ap9uMpADjLc0Bq72/utPZic3mCNXDSGbLmxMJQMNqF53AQr80ranDl3VgrLHp2ynNc=" Mar 25 06:02:17 katarynka go-librespot[29745]: time="2026-03-25T06:02:17+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:02:17 katarynka go-librespot[29745]: time="2026-03-25T06:02:17+01:00" level=debug msg="completed keyexchange" Mar 25 06:02:17 katarynka go-librespot[29745]: time="2026-03-25T06:02:17+01:00" level=debug msg="completed challenge" Mar 25 06:02:18 katarynka go-librespot[29745]: time="2026-03-25T06:02:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:02:18 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:02:18 katarynka volumio[29514]: info: Starting Shairport Sync Mar 25 06:02:18 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:02:18 katarynka volumio[29514]: info: Starting Shairport Sync Mar 25 06:02:18 katarynka volumio[29514]: info: Starting Shairport Sync Mar 25 06:02:18 katarynka sudo[29777]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 25 06:02:18 katarynka sudo[29777]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:18 katarynka sudo[29775]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 25 06:02:18 katarynka sudo[29775]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:18 katarynka sudo[29779]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 25 06:02:18 katarynka sudo[29779]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:18 katarynka volumio[29514]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 25 06:02:18 katarynka systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 25 06:02:18 katarynka systemd[1]: shairport-sync.service: Deactivated successfully. Mar 25 06:02:18 katarynka sudo[29782]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 25 06:02:18 katarynka systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 25 06:02:18 katarynka systemd[1]: shairport-sync.service: Consumed 2.273s CPU time. Mar 25 06:02:18 katarynka sudo[29782]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:18 katarynka systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 25 06:02:18 katarynka sudo[29777]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:18 katarynka volumio[29514]: info: Shairport-Sync Started Mar 25 06:02:18 katarynka volumio[29514]: Error adding Membership: Error: addMembership EINVAL Mar 25 06:02:18 katarynka volumio[29514]: info: CoreCommandRouter::volumioGetState Mar 25 06:02:18 katarynka volumio[29514]: info: CorePlayQueue::getTrack 0 Mar 25 06:02:18 katarynka systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 25 06:02:18 katarynka systemd[1]: shairport-sync.service: Deactivated successfully. Mar 25 06:02:18 katarynka systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 25 06:02:18 katarynka systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 25 06:02:18 katarynka sudo[29775]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:18 katarynka sudo[29779]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:18 katarynka volumio[29514]: info: Shairport-Sync Started Mar 25 06:02:18 katarynka volumio[29514]: info: Shairport-Sync Started Mar 25 06:02:18 katarynka sudo[29782]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:18 katarynka volumio[29514]: info: Upmpdcli Daemon Started Mar 25 06:02:20 katarynka volumio[29514]: info: go-librespot daemon successfully initialized Mar 25 06:02:21 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 25 06:02:21 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:21 katarynka mpd[29706]: 2026-03-25T06:02:21 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 25 06:02:21 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:21 katarynka go-librespot[29821]: go-librespot daemon starting... Mar 25 06:02:21 katarynka systemd[1]: Started mpd.service - Music Player Daemon. Mar 25 06:02:21 katarynka sudo[29671]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:21 katarynka sudo[29678]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:21 katarynka go-librespot[29824]: time="2026-03-25T06:02:21+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:02:21 katarynka go-librespot[29824]: time="2026-03-25T06:02:21+01:00" level=debug msg="app state loaded" Mar 25 06:02:21 katarynka go-librespot[29824]: time="2026-03-25T06:02:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:02:21 katarynka volumio[29514]: info: Completed starting Core Plugins Mar 25 06:02:21 katarynka volumio[29514]: info: ------------------------------------------- Mar 25 06:02:21 katarynka volumio[29514]: info: ----- MyVolumio plugins startup ---- Mar 25 06:02:21 katarynka volumio[29514]: info: ------------------------------------------- Mar 25 06:02:21 katarynka volumio[29514]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 25 06:02:21 katarynka volumio[29514]: error: MPD error: The expression evaluated to a falsy value: Mar 25 06:02:21 katarynka volumio[29514]: assert.ok(self.idling) Mar 25 06:02:21 katarynka volumio[29514]: error: The expression evaluated to a falsy value: Mar 25 06:02:21 katarynka volumio[29514]: assert.ok(self.idling) Mar 25 06:02:21 katarynka volumio[29514]: info: MPD running with PID29706 Mar 25 06:02:21 katarynka volumio[29514]: ,establishing connection Mar 25 06:02:21 katarynka volumio[29514]: error: updateQueue error: null Mar 25 06:02:21 katarynka volumio[29514]: error: updateQueue error: null Mar 25 06:02:21 katarynka go-librespot[29824]: time="2026-03-25T06:02:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:02:21 katarynka go-librespot[29824]: time="2026-03-25T06:02:21+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:02:21 katarynka go-librespot[29824]: time="2026-03-25T06:02:21+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:02:21 katarynka go-librespot[29824]: time="2026-03-25T06:02:21+01:00" level=info msg="zeroconf server listening on port 38659" Mar 25 06:02:21 katarynka go-librespot[29824]: time="2026-03-25T06:02:21+01:00" level=debug msg="obtained new client token: AABN7Tw8O1if4kJ4sw5lgPWn9nBPrU1hg9a+Txdn4INTPFKlb5mkbkXiSDCLVTUu/jhXY6sF+MKMVtZwcPGXEWZrhRApUUQ+MjUhXIJmsziS9L5CJhmcrYKfsiIlnViA7lqHxlyKBe7yONckXk3OVSK1J2N6o6DjoIvnlXYA052Rs6Gk3NA1Ow9uPLTWbKTjqBbVLfTpunEtt4b+CEhJIjHLo/Q3lS+ipMTORMq+1MQbgMMl2iXjnm0BYQ0=" Mar 25 06:02:21 katarynka go-librespot[29824]: time="2026-03-25T06:02:21+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:02:22 katarynka go-librespot[29824]: time="2026-03-25T06:02:22+01:00" level=debug msg="completed keyexchange" Mar 25 06:02:22 katarynka go-librespot[29824]: time="2026-03-25T06:02:22+01:00" level=debug msg="completed challenge" Mar 25 06:02:22 katarynka go-librespot[29824]: time="2026-03-25T06:02:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:02:22 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:02:22 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:02:23 katarynka volumio[29514]: info: Initializing connection to go-librespot Websocket Mar 25 06:02:23 katarynka volumio[29514]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 25 06:02:24 katarynka sudo[29848]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Mar 25 06:02:24 katarynka sudo[29848]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:24 katarynka sudo[29850]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Mar 25 06:02:24 katarynka sudo[29850]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:24 katarynka systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Mar 25 06:02:24 katarynka systemd[1]: mpd_monitor.service: Deactivated successfully. Mar 25 06:02:24 katarynka systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Mar 25 06:02:24 katarynka systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Mar 25 06:02:24 katarynka sudo[29850]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:24 katarynka sudo[29848]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:24 katarynka mpd_monitor.sh[29856]: MPD Monitor Service: Starting MPD Monitor Service Mar 25 06:02:24 katarynka volumio[29514]: info: Successfully started MPD Monitor Mar 25 06:02:24 katarynka volumio[29514]: info: Successfully started MPD Monitor Mar 25 06:02:25 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 25 06:02:25 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:25 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:25 katarynka go-librespot[29860]: go-librespot daemon starting... Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=debug msg="app state loaded" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=info msg="zeroconf server listening on port 46281" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=debug msg="obtained new client token: AAAZhoNMAaCZEzS+29cFEWYcLL3pqVrZXE9yXH3RUbpjksa3Bch34/hk8NjQT/KxLjNCc0yhf8/boXZYXZ3xMQuh+RyuDvSx8gMU+9DV5+vMrO0KoCDBF2etQr8WxTwXdbKh4de3kPVVL8o5Mm/PbiuMeGD/0kHMe1evjpdUS/8hSI/paLVu21gIuKv3Sg0S1W2RiGdL3ht2A7AZ6+HYCS5v16aLLtOexSrV2wRn637LnuQXt7mkCpWd2hA=" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=debug msg="completed keyexchange" Mar 25 06:02:25 katarynka go-librespot[29861]: time="2026-03-25T06:02:25+01:00" level=debug msg="completed challenge" Mar 25 06:02:26 katarynka go-librespot[29861]: time="2026-03-25T06:02:26+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:02:26 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:02:26 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:02:26 katarynka volumio[29514]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 25 06:02:27 katarynka volumio[29514]: info: Initializing connection to go-librespot Websocket Mar 25 06:02:27 katarynka volumio[29514]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 25 06:02:29 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Mar 25 06:02:29 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:29 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:29 katarynka go-librespot[29868]: go-librespot daemon starting... Mar 25 06:02:29 katarynka go-librespot[29869]: time="2026-03-25T06:02:29+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:02:29 katarynka go-librespot[29869]: time="2026-03-25T06:02:29+01:00" level=debug msg="app state loaded" Mar 25 06:02:29 katarynka go-librespot[29869]: time="2026-03-25T06:02:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:02:29 katarynka go-librespot[29869]: time="2026-03-25T06:02:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:02:29 katarynka go-librespot[29869]: time="2026-03-25T06:02:29+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:02:29 katarynka go-librespot[29869]: time="2026-03-25T06:02:29+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:02:29 katarynka go-librespot[29869]: time="2026-03-25T06:02:29+01:00" level=info msg="zeroconf server listening on port 42057" Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 25 06:02:29 katarynka volumio[29514]: info: Adding plugin bluetooth to MyMusic Plugins Mar 25 06:02:29 katarynka volumio[29514]: info: Adding plugin multiroom to MyMusic Plugins Mar 25 06:02:29 katarynka volumio[29514]: info: Adding plugin metavolumio to MyMusic Plugins Mar 25 06:02:29 katarynka volumio[29514]: info: Adding plugin cd_controller to MyMusic Plugins Mar 25 06:02:29 katarynka volumio[29514]: info: Adding plugin qobuzconnect to MyMusic Plugins Mar 25 06:02:29 katarynka volumio[29514]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 25 06:02:29 katarynka volumio[29514]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 25 06:02:29 katarynka volumio[29514]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 25 06:02:29 katarynka go-librespot[29869]: time="2026-03-25T06:02:29+01:00" level=debug msg="obtained new client token: AAA8pytFeo9L6djlGPkUOimf+KTq6sglbIISXPusue7MUOlNQeeqnTmyQKeLnLebsKVl96UER0IxTIu0jEmv7wabtXppL0FNRkYb2BasQkr8p8UYNFLrBAwDXvO2gfWHnehfp1tupUZJdrOBC8jLKo1/0lHEvwmnSb83N/BPAvDofyGMkzV/puoW7AIlGdhJuTyvyyQ44o9EIbVzM4qOKZ15pi6VX8eirb8uWl84MIO0Umv9shKw3ao1LUI=" Mar 25 06:02:29 katarynka go-librespot[29869]: time="2026-03-25T06:02:29+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:02:29 katarynka go-librespot[29869]: time="2026-03-25T06:02:29+01:00" level=debug msg="completed keyexchange" Mar 25 06:02:30 katarynka go-librespot[29869]: time="2026-03-25T06:02:30+01:00" level=debug msg="completed challenge" Mar 25 06:02:30 katarynka go-librespot[29869]: time="2026-03-25T06:02:30+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:02:30 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:02:30 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:02:31 katarynka volumio[29514]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 25 06:02:31 katarynka volumio[29514]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 25 06:02:31 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:31 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:31 katarynka volumio[29514]: info: Starting MyVolumio Remote Streaming Endpoints Mar 25 06:02:31 katarynka volumio[29514]: info: MyVolumio login type: Token Mar 25 06:02:31 katarynka volumio[29514]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 25 06:02:31 katarynka volumio[29514]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 25 06:02:33 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Mar 25 06:02:33 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:33 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:33 katarynka go-librespot[29876]: go-librespot daemon starting... Mar 25 06:02:33 katarynka go-librespot[29877]: time="2026-03-25T06:02:33+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:02:33 katarynka go-librespot[29877]: time="2026-03-25T06:02:33+01:00" level=debug msg="app state loaded" Mar 25 06:02:33 katarynka go-librespot[29877]: time="2026-03-25T06:02:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:02:33 katarynka volumio[29514]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 25 06:02:33 katarynka volumio[29514]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 25 06:02:33 katarynka volumio[29514]: info: Streaming services startup Mar 25 06:02:33 katarynka volumio[29514]: info: Starting Streaming Daemon Mar 25 06:02:33 katarynka sudo[29886]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 25 06:02:33 katarynka sudo[29886]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:33 katarynka go-librespot[29877]: time="2026-03-25T06:02:33+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:02:33 katarynka go-librespot[29877]: time="2026-03-25T06:02:33+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:02:33 katarynka go-librespot[29877]: time="2026-03-25T06:02:33+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:02:33 katarynka volumio[29514]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 25 06:02:33 katarynka go-librespot[29877]: time="2026-03-25T06:02:33+01:00" level=info msg="zeroconf server listening on port 44603" Mar 25 06:02:33 katarynka sudo[29886]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:33 katarynka volumio[29514]: info: Initializing connection to go-librespot Websocket Mar 25 06:02:33 katarynka volumio[29514]: error: Cannot start Volumio Streaming Daemon Mar 25 06:02:33 katarynka volumio[29514]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 25 06:02:33 katarynka volumio[29514]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 25 06:02:33 katarynka go-librespot[29877]: time="2026-03-25T06:02:33+01:00" level=debug msg="obtained new client token: AABthniD1axJe9kwpnngx7sh2O30fu6B0eJasI39mfg6XsVa5O7OGRsf7gw4dzJKrZZGLu6ap9bDZVD0dxX1zTZcAbyEzCAneronuFoV6sc++WEWwThSqvk1Nt52j2Wb7xgpi6nwO4d50ixPy4a/fw5xL7TPZs+7nrPAlW2lNtmV+B36LiZ22pFUr9b94IzfBDysoDFuER/MROptM8yfP7zit8QEqI96qgQiBPMY1rkJ+wFgzObx56f+GgY=" Mar 25 06:02:33 katarynka go-librespot[29877]: time="2026-03-25T06:02:33+01:00" level=debug msg="new websocket client" Mar 25 06:02:33 katarynka volumio[29514]: info: Connection to go-librespot Websocket established Mar 25 06:02:34 katarynka go-librespot[29877]: time="2026-03-25T06:02:34+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 06:02:34 katarynka go-librespot[29877]: time="2026-03-25T06:02:34+01:00" level=debug msg="completed keyexchange" Mar 25 06:02:34 katarynka go-librespot[29877]: time="2026-03-25T06:02:34+01:00" level=debug msg="completed challenge" Mar 25 06:02:34 katarynka volumio[29514]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Mar 25 06:02:34 katarynka go-librespot[29877]: time="2026-03-25T06:02:34+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 25 06:02:34 katarynka systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 25 06:02:34 katarynka systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 25 06:02:34 katarynka volumio[29514]: info: Connection to go-librespot Websocket closed Mar 25 06:02:35 katarynka volumio[29514]: info: MyVolumio token set successfully Mar 25 06:02:35 katarynka volumio[29514]: info: MYVOLUMIO: Adding device Mar 25 06:02:35 katarynka volumio[29514]: info: MYVOLUMIO: Evaluating Server Mar 25 06:02:35 katarynka volumio[29514]: info: MyVolumio status changed Mar 25 06:02:35 katarynka volumio[29514]: info: Streaming services startup Mar 25 06:02:35 katarynka volumio[29514]: info: Starting Streaming Daemon Mar 25 06:02:35 katarynka volumio[29514]: info: Removing browser output: myVolumio user plan is not superstar Mar 25 06:02:35 katarynka volumio[29514]: info: Removing audio output: Mar 25 06:02:35 katarynka volumio[29514]: info: Stoppping Tunnel 1 Mar 25 06:02:35 katarynka sudo[29928]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 25 06:02:35 katarynka sudo[29928]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:35 katarynka sudo[29930]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Mar 25 06:02:35 katarynka sudo[29930]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:35 katarynka sudo[29928]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:35 katarynka volumio[29514]: error: Cannot start Volumio Streaming Daemon Mar 25 06:02:35 katarynka volumio[29514]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 25 06:02:35 katarynka volumio[29514]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 25 06:02:35 katarynka 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. Mar 25 06:02:35 katarynka 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. Mar 25 06:02:35 katarynka 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. Mar 25 06:02:35 katarynka 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. Mar 25 06:02:35 katarynka 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. Mar 25 06:02:35 katarynka 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. Mar 25 06:02:35 katarynka 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. Mar 25 06:02:35 katarynka 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. Mar 25 06:02:35 katarynka sudo[29930]: pam_unix(sudo:session): session closed for user root Mar 25 06:02:35 katarynka volumio[29514]: info: Remote SSH Stopped Mar 25 06:02:36 katarynka volumio[29514]: info: Setting Geolocation for MyVolumio to eu7 Mar 25 06:02:36 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:36 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:36 katarynka volumio[29514]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 06:02:37 katarynka volumio[29514]: info: Getting Spotify volume Mar 25 06:02:37 katarynka volumio[29514]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 25 06:02:37 katarynka volumio[29514]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 25 06:02:37 katarynka volumio[29514]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 25 06:02:37 katarynka volumio[29514]: errno: -111, Mar 25 06:02:37 katarynka volumio[29514]: code: 'ECONNREFUSED', Mar 25 06:02:37 katarynka volumio[29514]: syscall: 'connect', Mar 25 06:02:37 katarynka volumio[29514]: address: '127.0.0.1', Mar 25 06:02:37 katarynka volumio[29514]: port: 9879, Mar 25 06:02:37 katarynka volumio[29514]: response: undefined Mar 25 06:02:37 katarynka volumio[29514]: } Mar 25 06:02:37 katarynka volumio[29514]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 25 06:02:38 katarynka systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Mar 25 06:02:38 katarynka systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:38 katarynka systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 06:02:38 katarynka go-librespot[29945]: go-librespot daemon starting... Mar 25 06:02:38 katarynka go-librespot[29946]: time="2026-03-25T06:02:38+01:00" level=info msg="running go-librespot 0.4.0" Mar 25 06:02:38 katarynka go-librespot[29946]: time="2026-03-25T06:02:38+01:00" level=debug msg="app state loaded" Mar 25 06:02:38 katarynka go-librespot[29946]: time="2026-03-25T06:02:38+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 06:02:38 katarynka sudo[29955]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-25 06:01' Mar 25 06:02:38 katarynka sudo[29955]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 06:02:38 katarynka go-librespot[29946]: time="2026-03-25T06:02:38+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 06:02:38 katarynka go-librespot[29946]: time="2026-03-25T06:02:38+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 06:02:38 katarynka go-librespot[29946]: time="2026-03-25T06:02:38+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 06:02:38 katarynka go-librespot[29946]: time="2026-03-25T06:02:38+01:00" level=info msg="zeroconf server listening on port 42137" 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"