Mar 26 20:40:06 volumio go-librespot[8376]: time="2026-03-26T20:40:06+01:00" level=trace msg="sent dealer ping" Mar 26 20:40:06 volumio go-librespot[8376]: time="2026-03-26T20:40:06+01:00" level=trace msg="received dealer pong" Mar 26 20:40:11 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:40:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:40:11 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:40:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:40:11 volumio volumio[1262]: info: Spotify config file written Mar 26 20:40:11 volumio sudo[8450]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:40:11 volumio sudo[8450]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:40:11 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:40:11 volumio systemd[1]: go-librespot-daemon.service: Killing process 8377 (go-librespot) with signal SIGKILL. Mar 26 20:40:11 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:40:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:11 volumio volumio[1262]: info: Connection to go-librespot Websocket closed Mar 26 20:40:11 volumio volumio[1262]: info: Connection to go-librespot Websocket closed Mar 26 20:40:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:11 volumio go-librespot[8452]: go-librespot daemon starting... Mar 26 20:40:11 volumio sudo[8450]: pam_unix(sudo:session): session closed for user root Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=debug msg="app state loaded" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=info msg="zeroconf server listening on port 42857" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=debug msg="obtained new client token: AAB0gozITbPbamOeBMrGiy12lZiHg5EPq7DZckSyPflGxOCNQYtyOy8uUxNTqfi2bZOfvPbPzj+Z4npf31IvOCvnMd+XUm3ZJVO648Pp/s01zylyuCLYc5mUZTCxE+4WySePXapnq51N3TFLvcUNb/BrlUk9I5GVNSq30Sphdh0FdQlGRHOpCQKKj/w3fVgJ30WyPoPp+j/JAEKUZANB0XR1DZvdGP1pnfYfspLrZG9i62fxRTl6xAU=" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=debug msg="completed keyexchange" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=debug msg="completed challenge" Mar 26 20:40:11 volumio go-librespot[8453]: time="2026-03-26T20:40:11+01:00" level=info msg="authenticated AP" username="jo*******iz" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=info msg="authenticated Login5" username="jo*******iz" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=debug msg="initializing zeroconf session" username="jo*******iz" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=debug msg="dealer connection opened" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=trace msg="starting accesspoint recv loop" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=trace msg="starting dealer recv loop" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=trace msg="received accesspoint ping" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=debug msg="received connection id: YzI3ZDI2YmUtMDg4...RDlEMUM0RkZCOQ==" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=trace msg="received accesspoint pong ack" Mar 26 20:40:12 volumio go-librespot[8453]: time="2026-03-26T20:40:12+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 26 20:40:12 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:40:12 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:40:12 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:40:12 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:40:12 volumio volumio[1262]: info: Spotify config file written Mar 26 20:40:12 volumio sudo[8463]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:40:12 volumio sudo[8463]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:40:12 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:40:12 volumio systemd[1]: go-librespot-daemon.service: Killing process 8461 (go-librespot) with signal SIGKILL. Mar 26 20:40:12 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:40:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:12 volumio go-librespot[8465]: go-librespot daemon starting... Mar 26 20:40:12 volumio sudo[8463]: pam_unix(sudo:session): session closed for user root Mar 26 20:40:12 volumio go-librespot[8466]: time="2026-03-26T20:40:12+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:40:12 volumio go-librespot[8466]: time="2026-03-26T20:40:12+01:00" level=debug msg="app state loaded" Mar 26 20:40:12 volumio go-librespot[8466]: time="2026-03-26T20:40:12+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:40:12 volumio go-librespot[8466]: time="2026-03-26T20:40:12+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 26 20:40:12 volumio go-librespot[8466]: time="2026-03-26T20:40:12+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 26 20:40:12 volumio go-librespot[8466]: time="2026-03-26T20:40:12+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 26 20:40:12 volumio go-librespot[8466]: time="2026-03-26T20:40:12+01:00" level=info msg="zeroconf server listening on port 41177" Mar 26 20:40:12 volumio go-librespot[8466]: time="2026-03-26T20:40:12+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 20:40:12 volumio go-librespot[8466]: time="2026-03-26T20:40:12+01:00" level=debug msg="obtained new client token: AAC6AHv/32Tm+LPAJW6fP6cSoCuTMrqYAquolsxJyjMlf18h7BnTAL+F2GVL+YN0/4DvtppaEqMalf6xzJuEI2NeXEYzqT95GJr3ZC7qkXl4eo7kL9IwojqC1yPOF4vJaPRbIo9mUloEZ7SdWhd8z3Aj6Csf7VspBMWqCoxn/Ucq3lOlXb83mFrgbxqfwUXgXYtyrjCedc0wp8escG8gB6QDAbCWPxi+zJsWS27+/AMdslwGSx3eIqA=" Mar 26 20:40:12 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:40:12 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:40:12 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:40:12 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:40:12 volumio volumio[1262]: info: Spotify config file written Mar 26 20:40:12 volumio sudo[8476]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:40:12 volumio sudo[8476]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:40:12 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:40:12 volumio systemd[1]: go-librespot-daemon.service: Killing process 8468 (go-librespot) with signal SIGKILL. Mar 26 20:40:12 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:40:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:13 volumio go-librespot[8478]: go-librespot daemon starting... Mar 26 20:40:13 volumio sudo[8476]: pam_unix(sudo:session): session closed for user root Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="app state loaded" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=info msg="zeroconf server listening on port 43959" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="obtained new client token: AACoQnoiVyoiDbglqIRSFzlGghZMP/KUeRkTqng2RlXLgnofdB7+KCZJbDKKKR+QNbH79RVxzr5GIyVWkMHwNjyUuhaV0qio3d5s9huoMENPOL79ME/J6aHOuNQJlLJjo/kEIvHGNSPzDvqjZZ14wnI2B2L77IuzZd9/Z0NzVjPOXA36b3qlR5j3/nRX1U7gcQiQEE72ERDBstnhPlp26/0BISzkRaHiF2737oY13BqfJumkCu6h" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="completed keyexchange" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="completed challenge" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=info msg="authenticated AP" username="jo*******iz" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=info msg="authenticated Login5" username="jo*******iz" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="initializing zeroconf session" username="jo*******iz" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="dealer connection opened" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=trace msg="starting accesspoint recv loop" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=trace msg="starting dealer recv loop" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=trace msg="received accesspoint ping" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="received connection id: YTM2YTY4NWMtMDRm...RjIwNzUwMzI2Mw==" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=trace msg="received accesspoint pong ack" Mar 26 20:40:13 volumio go-librespot[8479]: time="2026-03-26T20:40:13+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 26 20:40:14 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:14 volumio go-librespot[8479]: time="2026-03-26T20:40:14+01:00" level=debug msg="new websocket client" Mar 26 20:40:14 volumio volumio[1262]: info: Connection to go-librespot Websocket established Mar 26 20:40:14 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:40:15 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:40:15 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:40:15 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:40:15 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:40:15 volumio volumio[1262]: info: Spotify config file written Mar 26 20:40:15 volumio sudo[8489]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:40:15 volumio sudo[8489]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:40:15 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:40:15 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:40:15 volumio volumio[1262]: info: Connection to go-librespot Websocket closed Mar 26 20:40:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:15 volumio go-librespot[8491]: go-librespot daemon starting... Mar 26 20:40:15 volumio sudo[8489]: pam_unix(sudo:session): session closed for user root Mar 26 20:40:15 volumio go-librespot[8492]: time="2026-03-26T20:40:15+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:40:15 volumio go-librespot[8492]: time="2026-03-26T20:40:15+01:00" level=debug msg="app state loaded" Mar 26 20:40:15 volumio go-librespot[8492]: time="2026-03-26T20:40:15+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:40:15 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:40:15 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:40:15 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:40:15 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:40:15 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:40:15 volumio volumio[1262]: info: Spotify config file written Mar 26 20:40:15 volumio sudo[8501]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:40:15 volumio sudo[8501]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:40:15 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:40:15 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:40:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:15 volumio go-librespot[8503]: go-librespot daemon starting... Mar 26 20:40:15 volumio sudo[8501]: pam_unix(sudo:session): session closed for user root Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=debug msg="app state loaded" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=info msg="zeroconf server listening on port 43551" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=debug msg="obtained new client token: AADPQEk/wUNUEk6TnjpZoGGZ5Xe1gW/Z1ximJomPIsYDSDu/YER1qc6YUWuycKuwvbgcydux7Ixd3gPC37lCO63MxLg+/yfStrCG+Gk6kx8AhdYWe7G5vJ8NAwsp/Zt0mT+G2D7VGrdp1PzQzohSXdY9DQ0KcU0tafeo4jhN7cv/PtLsxarFO4JOYORDYVQemf9qo+w92NkDs7q10e9B9Vb5wQm6n66XI8PGDI2Qr99Hd+CdM66eDuA=" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=debug msg="completed keyexchange" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=debug msg="completed challenge" Mar 26 20:40:15 volumio go-librespot[8504]: time="2026-03-26T20:40:15+01:00" level=info msg="authenticated AP" username="jo*******iz" Mar 26 20:40:16 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=info msg="authenticated Login5" username="jo*******iz" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=debug msg="initializing zeroconf session" username="jo*******iz" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=debug msg="dealer connection opened" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=trace msg="starting accesspoint recv loop" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=trace msg="starting dealer recv loop" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=trace msg="received accesspoint ping" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=debug msg="received connection id: ZjNlN2JmNzEtMGI3...RTNFMjgxQjBGMQ==" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=trace msg="received accesspoint pong ack" Mar 26 20:40:16 volumio go-librespot[8504]: time="2026-03-26T20:40:16+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 26 20:40:17 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:40:17 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:40:17 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:40:17 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:40:17 volumio volumio[1262]: info: Spotify config file written Mar 26 20:40:17 volumio volumio[1262]: info: Getting Spotify volume Mar 26 20:40:17 volumio sudo[8514]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:40:17 volumio sudo[8514]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:40:17 volumio volumio[1262]: info: Spotify volume: 100 Mar 26 20:40:17 volumio volumio[1262]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Mar 26 20:40:17 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:40:17 volumio systemd[1]: go-librespot-daemon.service: Killing process 8508 (go-librespot) with signal SIGKILL. Mar 26 20:40:17 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:40:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:17 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 26 20:40:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 26 20:40:17 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:17 volumio sudo[8514]: pam_unix(sudo:session): session closed for user root Mar 26 20:40:17 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:40:17 volumio volumio[1262]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:40:17 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:40:17 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:40:17 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:40:17 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:40:17 volumio volumio[1262]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:40:17 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:40:17 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:40:17 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:40:17 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:40:17 volumio volumio[1262]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 26 20:40:17 volumio volumio[1262]: SPOTIFY: SPOTIFY VOLUME 100 Mar 26 20:40:17 volumio volumio[1262]: SPOTIFY: VOLUMIO VOLUME 46 Mar 26 20:40:17 volumio volumio[1262]: SPOTIFY: DELTA VOLUME ENOUGH: true Mar 26 20:40:17 volumio volumio[1262]: info: Setting Spotify Volume from Volumio: 46 Mar 26 20:40:17 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:17 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:17 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:40:17 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:40:17 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:40:17 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:40:17 volumio volumio[1262]: info: Spotify config file written Mar 26 20:40:17 volumio sudo[8517]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:40:17 volumio sudo[8517]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:40:17 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 26 20:40:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 26 20:40:17 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:17 volumio sudo[8517]: pam_unix(sudo:session): session closed for user root Mar 26 20:40:17 volumio volumio[1262]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:40:17 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:40:17 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:40:17 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:40:17 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:40:17 volumio volumio[1262]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:40:17 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:40:17 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:40:17 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:40:17 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:40:18 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:40:18 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:40:18 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:40:18 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:40:18 volumio volumio[1262]: info: Spotify config file written Mar 26 20:40:18 volumio sudo[8520]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:40:18 volumio sudo[8520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:40:18 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 26 20:40:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 26 20:40:18 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:40:18 volumio sudo[8520]: pam_unix(sudo:session): session closed for user root Mar 26 20:40:18 volumio volumio[1262]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:40:18 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:40:18 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:40:18 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:40:18 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:40:18 volumio volumio[1262]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:40:18 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:40:18 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:40:18 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:40:18 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:40:18 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:40:18 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:18 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:18 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:40:18 volumio volumio[1262]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Mar 26 20:40:18 volumio volumio[1262]: info: Sending Spotify command with payload to local API: /player/volume Mar 26 20:40:18 volumio volumio[1262]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:19 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:19 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:21 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:21 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:21 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:21 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:24 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:24 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:27 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:27 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:30 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:30 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:33 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:33 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:36 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:36 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:39 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:39 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:42 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:42 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:45 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:45 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:48 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:48 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:51 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:51 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:54 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:54 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:55 volumio volumio[1262]: verbose: New Socket.io Connection to 192.168.1.36 from 192.168.1.35 UA: Mozilla/5.0 (Linux; Android 16; SM-A546B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.119 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::volumioGetVisibleSources Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 26 20:40:55 volumio volumio[1262]: info: Received Get System Info Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 20:40:55 volumio volumio[1262]: info: Discovery: Getting this device information Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:40:55 volumio volumio[1262]: info: Listing playlists Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 20:40:55 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 26 20:40:57 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 26 20:40:57 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:40:57 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:40:57 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 26 20:40:57 volumio volumio[1262]: info: Received Get System Info Mar 26 20:40:57 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 20:40:57 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 20:40:57 volumio volumio[1262]: info: Discovery: Getting this device information Mar 26 20:40:57 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:40:57 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 20:40:58 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 26 20:40:58 volumio volumio[1262]: info: Received Get System Info Mar 26 20:40:58 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 20:40:58 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 20:40:58 volumio volumio[1262]: info: Discovery: Getting this device information Mar 26 20:40:58 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:40:58 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 20:41:00 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:41:00 volumio volumio[1262]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:41:01 volumio volumio[1262]: info: CALLMETHOD: music_service spop logout Mar 26 20:41:01 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , logout Mar 26 20:41:01 volumio volumio[1262]: info: Deleting Spotify credentials File Mar 26 20:41:01 volumio volumio[1262]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Mar 26 20:41:01 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 20:41:02 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:41:02 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:41:02 volumio volumio[1262]: info: Spotify config file written Mar 26 20:41:02 volumio sudo[8599]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:41:02 volumio sudo[8599]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:02 volumio go-librespot[8601]: go-librespot daemon starting... Mar 26 20:41:02 volumio sudo[8599]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:02 volumio go-librespot[8602]: time="2026-03-26T20:41:02+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:41:02 volumio go-librespot[8602]: time="2026-03-26T20:41:02+01:00" level=debug msg="no app state found" Mar 26 20:41:02 volumio go-librespot[8602]: time="2026-03-26T20:41:02+01:00" level=debug msg="stored credentials not found" Mar 26 20:41:02 volumio go-librespot[8602]: time="2026-03-26T20:41:02+01:00" level=info msg="generated new device id: 97bb1fb082719b3756f570577260b65b7546718c" Mar 26 20:41:02 volumio go-librespot[8602]: time="2026-03-26T20:41:02+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:41:02 volumio go-librespot[8602]: time="2026-03-26T20:41:02+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 26 20:41:02 volumio go-librespot[8602]: time="2026-03-26T20:41:02+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 26 20:41:02 volumio go-librespot[8602]: time="2026-03-26T20:41:02+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 26 20:41:02 volumio go-librespot[8602]: time="2026-03-26T20:41:02+01:00" level=info msg="zeroconf server listening on port 39913" Mar 26 20:41:02 volumio go-librespot[8602]: time="2026-03-26T20:41:02+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 20:41:03 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:41:03 volumio go-librespot[8602]: time="2026-03-26T20:41:03+01:00" level=debug msg="new websocket client" Mar 26 20:41:03 volumio volumio[1262]: info: Connection to go-librespot Websocket established Mar 26 20:41:05 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:41:05 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 26 20:41:06 volumio volumio[1262]: info: Getting Spotify volume Mar 26 20:41:06 volumio volumio[1262]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Mar 26 20:41:06 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:41:06 volumio volumio[1262]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 26 20:41:08 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:41:08 volumio go-librespot[8602]: time="2026-03-26T20:41:08+01:00" level=debug msg="new websocket client" Mar 26 20:41:08 volumio volumio[1262]: info: Connection to go-librespot Websocket established Mar 26 20:41:11 volumio volumio[1262]: info: Received OAUTH Data Mar 26 20:41:11 volumio volumio[1262]: info: Executing Spotify Oauth Login Mar 26 20:41:11 volumio volumio[1262]: info: Saving Spotify Refresh Token Mar 26 20:41:11 volumio sudo[8627]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 26 20:41:11 volumio sudo[8627]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:11 volumio sudo[8629]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 26 20:41:11 volumio sudo[8629]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:11 volumio sudo[8627]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:11 volumio sudo[8629]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:11 volumio volumio[1262]: verbose: New Socket.io Connection to 192.168.1.36 from 192.168.1.35 UA: Mozilla/5.0 (Linux; Android 16; SM-A546B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.119 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Mar 26 20:41:11 volumio volumio[1262]: info: Getting Spotify volume Mar 26 20:41:11 volumio volumio[1262]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Mar 26 20:41:11 volumio volumio[1262]: info: New Spotify access tokenBQBKYyPBcs... Mar 26 20:41:11 volumio volumio[1262]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:41:11 volumio volumio[1262]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::volumioGetVisibleSources Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 26 20:41:11 volumio volumio[1262]: info: Received Get System Info Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 20:41:11 volumio volumio[1262]: info: Discovery: Getting this device information Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:41:11 volumio volumio[1262]: info: Listing playlists Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 26 20:41:11 volumio volumio[1262]: SPOTIFY: User informations: {"country":"ES","display_name":"Jose Luis García Ortiz","email":"joselgortiz@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/joselgortiz"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/joselgortiz","id":"joselgortiz","images":[{"height":300,"url":"https://scontent-ams2-1.xx.fbcdn.net/v/t39.30808-1/464862193_8957395877626920_4156950690230912575_n.jpg?_nc_cat=109&ccb=1-7&_nc_sid=08baa4&_nc_ohc=dQjL5GRoLkIQ7kNvwEhlkLc&_nc_oc=Adro-QA6qO-Q2EoyHU4TjUfBdHUKBeH6X6fWuyUM7QEISt0Im7c8AVk5n1U7WFuoREtL-ETP7_GED7suHrel3jbN&_nc_zt=24&_nc_ht=scontent-ams2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=3E9Ny95cwBl44O_6xoNINQ&_nc_tpa=Q5bMBQGiHEYBZqOMCmPPrjs8ZBTdvrUdZkF38rddfPx6F3K_-gBGdV7h49K8bfPfkXUPXTqcxn_B&oh=00_AfyK0tzAGIvRaQA7IDPSAl6PJQzVZQnLlv05jksKBhysmQ&oe=69CB590E","width":300},{"height":64,"url":"https://scontent-ams2-1.xx.fbcdn.net/v/t39.30808-1/464862193_8957395877626920_4156950690230912575_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=109&ccb=1-7&_nc_sid=28885b&_nc_ohc=dQjL5GRoLkIQ7kNvwEhlkLc&_nc_oc=Adro-QA6qO-Q2EoyHU4TjUfBdHUKBeH6X6fWuyUM7QEISt0Im7c8AVk5n1U7WFuoREtL-ETP7_GED7suHrel3jbN&_nc_zt=24&_nc_ht=scontent-ams2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=3E9Ny95cwBl44O_6xoNINQ&_nc_tpa=Q5bMBQGJqAloF69phj_oR7DwNEow0APPhxdQ5R11BZQGWJ4E753hnC3nIu3tBc0oNylqE1XT9f_k&oh=00_AfzeRizZPTRtw8B7UHsUBHdCMuEcTiPQgJBO3d6vgvC5SQ&oe=69CB590E","width":64}],"product":"premium","type":"user","uri":"spotify:user:joselgortiz"} Mar 26 20:41:11 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:41:11 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:41:11 volumio volumio[1262]: info: Spotify config file written Mar 26 20:41:11 volumio sudo[8635]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:41:11 volumio sudo[8635]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:11 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:41:11 volumio systemd[1]: go-librespot-daemon.service: Killing process 8610 (go-librespot) with signal SIGKILL. Mar 26 20:41:11 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:41:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:11 volumio volumio[1262]: info: Connection to go-librespot Websocket closed Mar 26 20:41:11 volumio volumio[1262]: info: Connection to go-librespot Websocket closed Mar 26 20:41:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:11 volumio go-librespot[8638]: go-librespot daemon starting... Mar 26 20:41:11 volumio sudo[8635]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:11 volumio go-librespot[8639]: time="2026-03-26T20:41:11+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:41:11 volumio go-librespot[8639]: time="2026-03-26T20:41:11+01:00" level=debug msg="app state loaded" Mar 26 20:41:11 volumio go-librespot[8639]: time="2026-03-26T20:41:11+01:00" level=debug msg="stored credentials not found" Mar 26 20:41:11 volumio go-librespot[8639]: time="2026-03-26T20:41:11+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=info msg="zeroconf server listening on port 46433" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 20:41:12 volumio volumio[1262]: info: New Spotify access tokenBQDyuVSvxW... Mar 26 20:41:12 volumio volumio[1262]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="obtained new client token: AAAq5oI7h3W2pBySWCUu33OpI0HWc2GxsKSwVNwZ1Ka1K5f1lBxXCJfebOwby9o08uY1Yjsgr3doaRankWPqMLRjdEaDF2PduEGzBf1KIrqL0+zW9ZeZn8+Shwjw5tbSpvAmeeG4H+KsgXM/x1JrVJ61/0eTnrouau6tBk5J/EHfYut5emds14gvc+hkJw1FktG64RW2v0KepB2MpzzbhD/VT8H4+99D1TOxu/HdjRpMiwa54K2+" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="completed keyexchange" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="completed challenge" Mar 26 20:41:12 volumio volumio[1262]: SPOTIFY: User informations: {"country":"ES","display_name":"Jose Luis García Ortiz","email":"joselgortiz@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/joselgortiz"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/joselgortiz","id":"joselgortiz","images":[{"height":300,"url":"https://scontent-ams2-1.xx.fbcdn.net/v/t39.30808-1/464862193_8957395877626920_4156950690230912575_n.jpg?_nc_cat=109&ccb=1-7&_nc_sid=08baa4&_nc_ohc=dQjL5GRoLkIQ7kNvwEhlkLc&_nc_oc=Adro-QA6qO-Q2EoyHU4TjUfBdHUKBeH6X6fWuyUM7QEISt0Im7c8AVk5n1U7WFuoREtL-ETP7_GED7suHrel3jbN&_nc_zt=24&_nc_ht=scontent-ams2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=3E9Ny95cwBl44O_6xoNINQ&_nc_tpa=Q5bMBQGiHEYBZqOMCmPPrjs8ZBTdvrUdZkF38rddfPx6F3K_-gBGdV7h49K8bfPfkXUPXTqcxn_B&oh=00_AfyK0tzAGIvRaQA7IDPSAl6PJQzVZQnLlv05jksKBhysmQ&oe=69CB590E","width":300},{"height":64,"url":"https://scontent-ams2-1.xx.fbcdn.net/v/t39.30808-1/464862193_8957395877626920_4156950690230912575_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=109&ccb=1-7&_nc_sid=28885b&_nc_ohc=dQjL5GRoLkIQ7kNvwEhlkLc&_nc_oc=Adro-QA6qO-Q2EoyHU4TjUfBdHUKBeH6X6fWuyUM7QEISt0Im7c8AVk5n1U7WFuoREtL-ETP7_GED7suHrel3jbN&_nc_zt=24&_nc_ht=scontent-ams2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=3E9Ny95cwBl44O_6xoNINQ&_nc_tpa=Q5bMBQGJqAloF69phj_oR7DwNEow0APPhxdQ5R11BZQGWJ4E753hnC3nIu3tBc0oNylqE1XT9f_k&oh=00_AfzeRizZPTRtw8B7UHsUBHdCMuEcTiPQgJBO3d6vgvC5SQ&oe=69CB590E","width":64}],"product":"premium","type":"user","uri":"spotify:user:joselgortiz"} Mar 26 20:41:12 volumio volumio[1262]: info: Spotify Successfully logged in Mar 26 20:41:12 volumio volumio[1262]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 26 20:41:12 volumio volumio[1262]: info: [1774554072263] CoreMusicLibrary::Adding element Spotify Mar 26 20:41:12 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 20:41:12 volumio volumio[1262]: Cannot find translation for source Spotify Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=info msg="authenticated AP" username="jo*******iz" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=info msg="authenticated Login5" username="jo*******iz" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="stored credentials" username="jo*******iz" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="initializing zeroconf session" username="jo*******iz" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="dealer connection opened" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=trace msg="starting accesspoint recv loop" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=trace msg="starting dealer recv loop" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=trace msg="received accesspoint ping" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="received connection id: N2Q1NjI0MDQtN2Qz...RkM0RjZDMUM1OA==" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=trace msg="received accesspoint pong ack" Mar 26 20:41:12 volumio go-librespot[8639]: time="2026-03-26T20:41:12+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 26 20:41:13 volumio volumio[1262]: info: Received Get System Info Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 20:41:13 volumio volumio[1262]: info: Discovery: Getting this device information Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 26 20:41:13 volumio volumio[1262]: info: Received Get System Info Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 20:41:13 volumio volumio[1262]: info: Discovery: Getting this device information Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:41:13 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 20:41:14 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:41:14 volumio go-librespot[8639]: time="2026-03-26T20:41:14+01:00" level=debug msg="new websocket client" Mar 26 20:41:14 volumio volumio[1262]: info: Connection to go-librespot Websocket established Mar 26 20:41:14 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:41:17 volumio volumio[1262]: info: Getting Spotify volume Mar 26 20:41:17 volumio volumio[1262]: info: Spotify volume: 100 Mar 26 20:41:17 volumio volumio[1262]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Mar 26 20:41:17 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:41:17 volumio volumio[1262]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 26 20:41:17 volumio volumio[1262]: SPOTIFY: SPOTIFY VOLUME 100 Mar 26 20:41:17 volumio volumio[1262]: SPOTIFY: VOLUMIO VOLUME 46 Mar 26 20:41:17 volumio volumio[1262]: SPOTIFY: DELTA VOLUME ENOUGH: true Mar 26 20:41:17 volumio volumio[1262]: info: Setting Spotify Volume from Volumio: 46 Mar 26 20:41:17 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:41:17 volumio go-librespot[8639]: time="2026-03-26T20:41:17+01:00" level=debug msg="new websocket client" Mar 26 20:41:17 volumio volumio[1262]: info: Connection to go-librespot Websocket established Mar 26 20:41:19 volumio volumio[1262]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Mar 26 20:41:19 volumio volumio[1262]: info: Sending Spotify command with payload to local API: /player/volume Mar 26 20:41:19 volumio go-librespot[8639]: time="2026-03-26T20:41:19+01:00" level=debug msg="update volume requested to 30146/65535" Mar 26 20:41:19 volumio go-librespot[8639]: time="2026-03-26T20:41:19+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 26 20:41:19 volumio go-librespot[8639]: time="2026-03-26T20:41:19+01:00" level=trace msg="emitting websocket event: volume" Mar 26 20:41:19 volumio volumio[1262]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Mar 26 20:41:19 volumio volumio[1262]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Mar 26 20:41:19 volumio volumio[1262]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Mar 26 20:41:19 volumio volumio[1262]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Mar 26 20:41:20 volumio volumio[1262]: info: Getting Spotify volume Mar 26 20:41:20 volumio volumio[1262]: info: Spotify volume: 46 Mar 26 20:41:20 volumio volumio[1262]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Mar 26 20:41:20 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:41:20 volumio volumio[1262]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 26 20:41:21 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 26 20:41:29 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 26 20:41:29 volumio volumio[1262]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 26 20:41:29 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 26 20:41:29 volumio volumio[1262]: info: Received Get System Version Mar 26 20:41:29 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 26 20:41:29 volumio volumio[1262]: info: Received Get System Info Mar 26 20:41:29 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 20:41:29 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 20:41:29 volumio volumio[1262]: info: Discovery: Getting this device information Mar 26 20:41:29 volumio volumio[1262]: info: CoreCommandRouter::volumioGetState Mar 26 20:41:29 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 20:41:35 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:41:35 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:41:35 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:41:35 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:41:35 volumio volumio[1262]: info: Spotify config file written Mar 26 20:41:35 volumio sudo[8680]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:41:35 volumio sudo[8680]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:35 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:41:35 volumio systemd[1]: go-librespot-daemon.service: Killing process 8644 (go-librespot) with signal SIGKILL. Mar 26 20:41:35 volumio volumio[1262]: info: Connection to go-librespot Websocket closed Mar 26 20:41:35 volumio volumio[1262]: info: Connection to go-librespot Websocket closed Mar 26 20:41:35 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:41:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:35 volumio sudo[8680]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:35 volumio go-librespot[8682]: go-librespot daemon starting... Mar 26 20:41:35 volumio go-librespot[8683]: time="2026-03-26T20:41:35+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:41:35 volumio go-librespot[8683]: time="2026-03-26T20:41:35+01:00" level=debug msg="app state loaded" Mar 26 20:41:35 volumio go-librespot[8683]: time="2026-03-26T20:41:35+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=info msg="zeroconf server listening on port 39691" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="obtained new client token: AAAKGOa4sTmYDgmsI+l3izaLRlwGaeqTftzOpOdPF7fksCzFX0QxFWv8GkRNieayEI5oLnF2OBs7jILD2tRUbARPMPQtl8f0/01K6NnJXcgB5hWWAfP5WKpHOb//wvN9A8jjKs02BxWphdbsocn2bfMdyYNWQgGP5hKOKvLej1ChUDHDo/Pc/18O58IxFtmDPlkJqps87I8BLI7RTYEX+djrWVhJdhJgodQJJeM5wxbly+5hd05w" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="completed keyexchange" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="completed challenge" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=info msg="authenticated AP" username="jo*******iz" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=info msg="authenticated Login5" username="jo*******iz" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="initializing zeroconf session" username="jo*******iz" Mar 26 20:41:36 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:41:36 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:41:36 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:41:36 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:41:36 volumio volumio[1262]: info: Spotify config file written Mar 26 20:41:36 volumio sudo[8694]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:41:36 volumio sudo[8694]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="dealer connection opened" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=trace msg="starting accesspoint recv loop" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=trace msg="starting dealer recv loop" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=trace msg="received accesspoint ping" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 26 20:41:36 volumio go-librespot[8683]: time="2026-03-26T20:41:36+01:00" level=debug msg="received connection id: ZmU4ODQ5ZDItZTQz...MDFBQjUyMjlGQw==" Mar 26 20:41:36 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:41:36 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:41:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:36 volumio go-librespot[8696]: go-librespot daemon starting... Mar 26 20:41:36 volumio sudo[8694]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:36 volumio go-librespot[8697]: time="2026-03-26T20:41:36+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:41:36 volumio go-librespot[8697]: time="2026-03-26T20:41:36+01:00" level=debug msg="app state loaded" Mar 26 20:41:36 volumio go-librespot[8697]: time="2026-03-26T20:41:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:41:36 volumio go-librespot[8697]: time="2026-03-26T20:41:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 26 20:41:36 volumio go-librespot[8697]: time="2026-03-26T20:41:36+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 26 20:41:36 volumio go-librespot[8697]: time="2026-03-26T20:41:36+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 26 20:41:36 volumio go-librespot[8697]: time="2026-03-26T20:41:36+01:00" level=info msg="zeroconf server listening on port 44893" Mar 26 20:41:36 volumio go-librespot[8697]: time="2026-03-26T20:41:36+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 20:41:36 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:41:36 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:41:36 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:41:36 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:41:36 volumio volumio[1262]: info: Spotify config file written Mar 26 20:41:36 volumio sudo[8707]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:41:36 volumio sudo[8707]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:36 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:41:36 volumio systemd[1]: go-librespot-daemon.service: Killing process 8700 (go-librespot) with signal SIGKILL. Mar 26 20:41:36 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:41:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:36 volumio go-librespot[8709]: go-librespot daemon starting... Mar 26 20:41:36 volumio sudo[8707]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:36 volumio go-librespot[8710]: time="2026-03-26T20:41:36+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:41:36 volumio go-librespot[8710]: time="2026-03-26T20:41:36+01:00" level=debug msg="app state loaded" Mar 26 20:41:36 volumio go-librespot[8710]: time="2026-03-26T20:41:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:41:36 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:41:36 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:41:36 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:41:36 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:41:36 volumio volumio[1262]: info: Spotify config file written Mar 26 20:41:37 volumio sudo[8720]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:41:37 volumio sudo[8720]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:37 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:41:37 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:41:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:37 volumio go-librespot[8722]: go-librespot daemon starting... Mar 26 20:41:37 volumio sudo[8720]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="app state loaded" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=info msg="zeroconf server listening on port 36291" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="obtained new client token: AAC70H5SEaI4LD4JnOB7fHPDljfzDTYzAFCPTE6uEo9ZjB74Qmff2zXqYu4vNw0RcDC5uvOSYQmwypnpgoGGFv21LVWNywYU4uvySu540iqb5VVUOG+/76I5G/Dc2GTO3RyqPeN36kZmGhafev56PI35U48Cr3kbeXYoy2ur9lHaUUuWOLUBlU+x50O4f/BE0WwXKDTxRAq0v8GpWCyr6BufwnaajWipWTrEee2w661H7sXvqzOzhrY=" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="completed keyexchange" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="completed challenge" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=info msg="authenticated AP" username="jo*******iz" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=info msg="authenticated Login5" username="jo*******iz" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="initializing zeroconf session" username="jo*******iz" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="dealer connection opened" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=trace msg="starting accesspoint recv loop" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=trace msg="starting dealer recv loop" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=trace msg="received accesspoint ping" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="received connection id: ODI2NDU0MzEtNmY2...NEVDNDlENEMxQQ==" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=trace msg="received accesspoint pong ack" Mar 26 20:41:37 volumio go-librespot[8723]: time="2026-03-26T20:41:37+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 26 20:41:38 volumio volumio[1262]: info: Initializing connection to go-librespot Websocket Mar 26 20:41:38 volumio volumio[1262]: info: Connection to go-librespot Websocket established Mar 26 20:41:38 volumio go-librespot[8723]: time="2026-03-26T20:41:38+01:00" level=debug msg="new websocket client" Mar 26 20:41:38 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:41:39 volumio volumio[1262]: info: CoreCommandRouter::volumioPause Mar 26 20:41:39 volumio volumio[1262]: info: CoreStateMachine::pause Mar 26 20:41:39 volumio volumio[1262]: info: CoreStateMachine::stPlaybackTimer Mar 26 20:41:39 volumio volumio[1262]: info: CoreStateMachine::servicePause Mar 26 20:41:39 volumio volumio[1262]: info: CoreCommandRouter::servicePause Mar 26 20:41:39 volumio volumio[1262]: info: Spotify Received pause Mar 26 20:41:39 volumio volumio[1262]: SPOTIFY: SPOTIFY PAUSE Mar 26 20:41:39 volumio volumio[1262]: SPOTIFY: {"status":"play","title":"L'attimo presente","artist":"Riccardo Cocciante","album":"Innamorato","albumart":"https://i.scdn.co/image/ab67616d00001e0210bad41b7d357b127fb05ff3","uri":"spotify:track:3z07QupX0WAGGsUb7N9dbk","trackType":"spotify","codec":"ogg","seek":557852,"duration":301,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":46,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Mar 26 20:41:39 volumio volumio[1262]: info: Sending Spotify command to local API: /player/pause Mar 26 20:41:39 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:41:39 volumio volumio[1262]: info: CoreCommandRouter::volumioPause Mar 26 20:41:39 volumio volumio[1262]: info: CoreStateMachine::pause Mar 26 20:41:39 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:41:40 volumio volumio[1262]: info: go-librespot daemon successfully initialized Mar 26 20:41:40 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:41:40 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:41:40 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:41:40 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:41:40 volumio volumio[1262]: info: Spotify config file written Mar 26 20:41:40 volumio sudo[8747]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:41:40 volumio sudo[8747]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:40 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:41:40 volumio systemd[1]: go-librespot-daemon.service: Killing process 8725 (go-librespot) with signal SIGKILL. Mar 26 20:41:40 volumio volumio[1262]: info: Connection to go-librespot Websocket closed Mar 26 20:41:40 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:41:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:41 volumio go-librespot[8749]: go-librespot daemon starting... Mar 26 20:41:41 volumio sudo[8747]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:41 volumio go-librespot[8750]: time="2026-03-26T20:41:41+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 20:41:41 volumio go-librespot[8750]: time="2026-03-26T20:41:41+01:00" level=debug msg="app state loaded" Mar 26 20:41:41 volumio go-librespot[8750]: time="2026-03-26T20:41:41+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 20:41:41 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:41:41 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:41:41 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:41:41 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:41:41 volumio volumio[1262]: info: Spotify config file written Mar 26 20:41:41 volumio go-librespot[8750]: time="2026-03-26T20:41:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 26 20:41:41 volumio go-librespot[8750]: time="2026-03-26T20:41:41+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 26 20:41:41 volumio go-librespot[8750]: time="2026-03-26T20:41:41+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 26 20:41:41 volumio go-librespot[8750]: time="2026-03-26T20:41:41+01:00" level=info msg="zeroconf server listening on port 35117" Mar 26 20:41:41 volumio go-librespot[8750]: time="2026-03-26T20:41:41+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 20:41:41 volumio sudo[8762]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:41:41 volumio sudo[8762]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:41 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 26 20:41:41 volumio systemd[1]: go-librespot-daemon.service: Killing process 8756 (go-librespot) with signal SIGKILL. Mar 26 20:41:41 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 26 20:41:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:41 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 26 20:41:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 26 20:41:41 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:41 volumio sudo[8762]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:41 volumio volumio[1262]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:41:41 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:41:41 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:41:41 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:41:41 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:41:41 volumio volumio[1262]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:41:41 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:41:41 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:41:41 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:41:41 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:41:41 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:41:41 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:41:41 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:41:41 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:41:41 volumio volumio[1262]: info: Spotify config file written Mar 26 20:41:41 volumio sudo[8765]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:41:41 volumio sudo[8765]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:41 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 26 20:41:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 26 20:41:41 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:41 volumio sudo[8765]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:41 volumio volumio[1262]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:41:41 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:41:41 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:41:41 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:41:41 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:41:41 volumio volumio[1262]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:41:41 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:41:41 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:41:41 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:41:41 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:41:41 volumio volumio[1262]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 26 20:41:41 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 26 20:41:41 volumio volumio[1262]: info: Creating Spotify config file Mar 26 20:41:41 volumio volumio[1262]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 20:41:41 volumio volumio[1262]: info: Spotify config file written Mar 26 20:41:41 volumio sudo[8768]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 20:41:41 volumio sudo[8768]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 20:41:41 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 26 20:41:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 26 20:41:41 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 26 20:41:41 volumio sudo[8768]: pam_unix(sudo:session): session closed for user root Mar 26 20:41:41 volumio volumio[1262]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:41:41 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:41:41 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:41:41 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:41:41 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:41:41 volumio volumio[1262]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 26 20:41:41 volumio volumio[1262]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 26 20:41:41 volumio volumio[1262]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 26 20:41:41 volumio volumio[1262]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 26 20:41:41 volumio volumio[1262]: followed by "systemctl start go-librespot-daemon.service" again. Mar 26 20:41:41 volumio volumio[1262]: info: Getting Spotify volume Mar 26 20:41:41 volumio volumio[1262]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 26 20:41:41 volumio volumio[1262]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 26 20:41:41 volumio volumio[1262]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 26 20:41:41 volumio volumio[1262]: errno: -111, Mar 26 20:41:41 volumio volumio[1262]: code: 'ECONNREFUSED', Mar 26 20:41:41 volumio volumio[1262]: syscall: 'connect', Mar 26 20:41:41 volumio volumio[1262]: address: '127.0.0.1', Mar 26 20:41:41 volumio volumio[1262]: port: 9879, Mar 26 20:41:41 volumio volumio[1262]: response: undefined Mar 26 20:41:41 volumio volumio[1262]: } Mar 26 20:41:41 volumio volumio[1262]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 26 20:41:42 volumio sudo[8784]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-26 20:40' Mar 26 20:41:42 volumio sudo[8784]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"