Dec 09 15:30:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 156. Dec 09 15:30:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:00 volumio go-librespot[30430]: go-librespot daemon starting... Dec 09 15:30:01 volumio go-librespot[30431]: time="2025-12-09T15:30:01-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:01 volumio go-librespot[30431]: time="2025-12-09T15:30:01-06:00" level=debug msg="app state loaded" Dec 09 15:30:01 volumio go-librespot[30431]: time="2025-12-09T15:30:01-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:01 volumio go-librespot[30431]: time="2025-12-09T15:30:01-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:01 volumio go-librespot[30431]: time="2025-12-09T15:30:01-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 09 15:30:01 volumio go-librespot[30431]: time="2025-12-09T15:30:01-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 09 15:30:01 volumio go-librespot[30431]: time="2025-12-09T15:30:01-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 09 15:30:01 volumio go-librespot[30431]: time="2025-12-09T15:30:01-06:00" level=info msg="zeroconf server listening on port 44777" Dec 09 15:30:01 volumio go-librespot[30431]: time="2025-12-09T15:30:01-06:00" level=debug msg="obtained new client token: AADa9IGxpbY7iFzRylNlhJpwIiFAmXldJwmHftjQLHML8IgrclF/xwYHF6KsvBR5Z8MtZf+tASsucaLThy7qfc7wyPjrJ3bvDIo9AzeGC3YdZw4+kF1v0M21WTUR/sdkWOAlwqxDxz/NY6i9mnGUJyJ46kGECFe+0strz1GMbXd1/zoH1iGJqoMTO9pnJOsZBgwF0UllLRncn3mkeLQQT4mOk4bsbznRtV/27A1NlWkrRr1i0MH+WisiRQ==" Dec 09 15:30:02 volumio go-librespot[30431]: time="2025-12-09T15:30:02-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:02 volumio go-librespot[30431]: time="2025-12-09T15:30:02-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:02 volumio go-librespot[30431]: time="2025-12-09T15:30:02-06:00" level=debug msg="completed challenge" Dec 09 15:30:02 volumio go-librespot[30431]: time="2025-12-09T15:30:02-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:02 volumio volumio[29655]: info: Initializing connection to go-librespot Websocket Dec 09 15:30:02 volumio volumio[29655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 15:30:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 157. Dec 09 15:30:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:05 volumio volumio[29655]: info: Initializing connection to go-librespot Websocket Dec 09 15:30:05 volumio volumio[29655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 15:30:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:05 volumio go-librespot[30439]: go-librespot daemon starting... Dec 09 15:30:05 volumio go-librespot[30440]: time="2025-12-09T15:30:05-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:05 volumio go-librespot[30440]: time="2025-12-09T15:30:05-06:00" level=debug msg="app state loaded" Dec 09 15:30:05 volumio go-librespot[30440]: time="2025-12-09T15:30:05-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:05 volumio go-librespot[30440]: time="2025-12-09T15:30:05-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:05 volumio go-librespot[30440]: time="2025-12-09T15:30:05-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:05 volumio go-librespot[30440]: time="2025-12-09T15:30:05-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:05 volumio go-librespot[30440]: time="2025-12-09T15:30:05-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:05 volumio go-librespot[30440]: time="2025-12-09T15:30:05-06:00" level=info msg="zeroconf server listening on port 39841" Dec 09 15:30:06 volumio go-librespot[30440]: time="2025-12-09T15:30:06-06:00" level=debug msg="obtained new client token: AAClN1/mnK3FuPxFEKu94Iu3yYN38BNnhtMQq4lEm0R3cpTcFZqj9qNED/04eOF5J8+IX506ERqVPAh9icAJBd+srf9+HcCd787MjkuLz+sSPq9yxLoPAkrHJeBBZCFoXRAUebjKwvWuu+DIh2gKDZE5TE70oQwGjml5N4eaDEzUUEXGc091WksU02SSLeuATI3+FwVSOot8hdzaT02aHZWO7Q0rGIeZnZ3rlvMR9VrfHk+LXRhVrds=" Dec 09 15:30:06 volumio go-librespot[30440]: time="2025-12-09T15:30:06-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:06 volumio go-librespot[30440]: time="2025-12-09T15:30:06-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:06 volumio go-librespot[30440]: time="2025-12-09T15:30:06-06:00" level=debug msg="completed challenge" Dec 09 15:30:06 volumio go-librespot[30440]: time="2025-12-09T15:30:06-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:08 volumio volumio[29655]: info: Initializing connection to go-librespot Websocket Dec 09 15:30:08 volumio volumio[29655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 15:30:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 158. Dec 09 15:30:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:09 volumio go-librespot[30461]: go-librespot daemon starting... Dec 09 15:30:09 volumio go-librespot[30462]: time="2025-12-09T15:30:09-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:09 volumio go-librespot[30462]: time="2025-12-09T15:30:09-06:00" level=debug msg="app state loaded" Dec 09 15:30:09 volumio go-librespot[30462]: time="2025-12-09T15:30:09-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:09 volumio go-librespot[30462]: time="2025-12-09T15:30:09-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:09 volumio go-librespot[30462]: time="2025-12-09T15:30:09-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:09 volumio go-librespot[30462]: time="2025-12-09T15:30:09-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:09 volumio go-librespot[30462]: time="2025-12-09T15:30:09-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:09 volumio go-librespot[30462]: time="2025-12-09T15:30:09-06:00" level=info msg="zeroconf server listening on port 39859" Dec 09 15:30:10 volumio go-librespot[30462]: time="2025-12-09T15:30:10-06:00" level=debug msg="obtained new client token: AACSW9K8t56X+rsEdN2F+tFXsKzpwOynrhzflajVw+fD885q+mcSstxNjHpx0lXFq5IwNXy6wx6VXlxMfSoKVyNraF0q5RZOI4ajk11rgMoCxDYXZO9UgWHR5txoiBBpUqMN/mlwY09pUlL+eKoL87i0GI4JuXjE/CBNEoi2gvKfEc8OqD3D2wSBf5FkdcoMQuGsWUAz3NmDiR90DbyfaDx0tPhkzQa55eOOxWNTGSb7M0g6kisAwvA=" Dec 09 15:30:10 volumio go-librespot[30462]: time="2025-12-09T15:30:10-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:10 volumio go-librespot[30462]: time="2025-12-09T15:30:10-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:10 volumio go-librespot[30462]: time="2025-12-09T15:30:10-06:00" level=debug msg="completed challenge" Dec 09 15:30:10 volumio go-librespot[30462]: time="2025-12-09T15:30:10-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:11 volumio volumio[29655]: info: Initializing connection to go-librespot Websocket Dec 09 15:30:11 volumio volumio[29655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 15:30:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 159. Dec 09 15:30:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:13 volumio go-librespot[30469]: go-librespot daemon starting... Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=debug msg="app state loaded" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=info msg="zeroconf server listening on port 45055" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=debug msg="obtained new client token: AAA4/vFpWbWcA62+2ByrVUpEbjGDF9xEDCYdOmmU3YrwI3Ify0bmUsBaUERsG+ilDnKO9sGFO+jOjjECDj5/ftuMZNUxWG+hps/ZCag45PvHPiKfHQg67MqGMaJd74JpyeH7Kejf7uTKqpzYQJV2Rw+pQTrpvK+RWbuu6xgHrTjXhcL6otcmPKw+twdbh/nMuY/xpU48cyOo8snq+Qm6QNSsrWuHe036Xnpk/5nfx0uXm9ahB167gIyrjg==" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:13 volumio go-librespot[30470]: time="2025-12-09T15:30:13-06:00" level=debug msg="completed challenge" Dec 09 15:30:14 volumio go-librespot[30470]: time="2025-12-09T15:30:14-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:14 volumio volumio[29655]: info: Initializing connection to go-librespot Websocket Dec 09 15:30:14 volumio volumio[29655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 15:30:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 160. Dec 09 15:30:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:17 volumio go-librespot[30491]: go-librespot daemon starting... Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=debug msg="app state loaded" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:17 volumio volumio[29655]: info: Initializing connection to go-librespot Websocket Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=debug msg="new websocket client" Dec 09 15:30:17 volumio volumio[29655]: info: Connection to go-librespot Websocket established Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=info msg="zeroconf server listening on port 45737" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=debug msg="obtained new client token: AAAf16x5nVrLbHKcTIqa/2qhIuIgxE+ibBHfP+ZONIJ4dH5f84YNPEcAuCCvEIfQFBVxGqhpWBcGYa/vVkz/faUlIwtn7Mezgvo/2jFrrKxtG81pqsBUOof4OrGez8ZVvF3t8xq/xr9UCRIoWMF+rDfNUBH+ZLSwtQjC0Oz/SFBt2sz020L8KgqQcmyhZhuDv4oygh5wSBQqLKYtnL1amR/5+1yDXgwuQLqhl0qGvXronDTk82N0vp8zzg==" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=debug msg="completed challenge" Dec 09 15:30:17 volumio go-librespot[30492]: time="2025-12-09T15:30:17-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:17 volumio volumio[29655]: info: Connection to go-librespot Websocket closed Dec 09 15:30:20 volumio volumio[29655]: info: Getting Spotify volume Dec 09 15:30:20 volumio volumio[29655]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 15:30:20 volumio volumio[29655]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 15:30:20 volumio volumio[29655]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 09 15:30:20 volumio volumio[29655]: errno: -111, Dec 09 15:30:20 volumio volumio[29655]: code: 'ECONNREFUSED', Dec 09 15:30:20 volumio volumio[29655]: syscall: 'connect', Dec 09 15:30:20 volumio volumio[29655]: address: '127.0.0.1', Dec 09 15:30:20 volumio volumio[29655]: port: 9879, Dec 09 15:30:20 volumio volumio[29655]: response: undefined Dec 09 15:30:20 volumio volumio[29655]: } Dec 09 15:30:20 volumio volumio[29655]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 15:30:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 161. Dec 09 15:30:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:21 volumio go-librespot[30514]: go-librespot daemon starting... Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=debug msg="app state loaded" Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=info msg="zeroconf server listening on port 36111" Dec 09 15:30:21 volumio sudo[30525]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 15:29' Dec 09 15:30:21 volumio sudo[30525]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=debug msg="obtained new client token: AADftHG4XajJj4MbX1pk7ciGraPnoLl9Z52Ak06Mu87JhIW/hIBYY4e9TtcLKfdeWC7pA3Jkdfe+NGIg1U9jwy2XaIoOPkKWD0QjecKx+Ltg1Bx/MHFLWQTLfyzpHX09B6z1sWF1rpuDQ/mfL7GTosrvqzLEVBIhY5WQMqyRv0/XLzZm2IdobM7UWwkz8aG2eRNE3i17tJhgj3zFYvkpTUdehmufo+/rgNfKpXy/MM6tsiDUgp9B02QBrw==" Dec 09 15:30:21 volumio sudo[30525]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=debug msg="completed challenge" Dec 09 15:30:21 volumio go-librespot[30515]: time="2025-12-09T15:30:21-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:22 volumio volumio-remote-updater[9752]: [2025-12-09 15:30:22] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 09 15:30:22 volumio volumio-remote-updater[9752]: [2025-12-09 15:30:22] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 09 15:30:22 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:22 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 09 15:30:22 volumio systemd[1]: volumio.service: Consumed 51.158s CPU time. Dec 09 15:30:22 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 09 15:30:22 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 09 15:30:22 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 24593. Dec 09 15:30:22 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 09 15:30:22 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 09 15:30:22 volumio systemd[1]: volumio.service: Consumed 51.158s CPU time. Dec 09 15:30:22 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 09 15:30:22 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 09 15:30:24 volumio volumio[30543]: info: ------------------------------------------- Dec 09 15:30:24 volumio volumio[30543]: info: ----- Volumio3 ---- Dec 09 15:30:24 volumio volumio[30543]: info: ------------------------------------------- Dec 09 15:30:24 volumio volumio[30543]: info: ----- System startup ---- Dec 09 15:30:24 volumio volumio[30543]: info: ------------------------------------------- Dec 09 15:30:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 162. Dec 09 15:30:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:24 volumio go-librespot[30564]: go-librespot daemon starting... Dec 09 15:30:24 volumio go-librespot[30565]: time="2025-12-09T15:30:24-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:24 volumio go-librespot[30565]: time="2025-12-09T15:30:24-06:00" level=debug msg="app state loaded" Dec 09 15:30:24 volumio go-librespot[30565]: time="2025-12-09T15:30:24-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:24 volumio go-librespot[30565]: time="2025-12-09T15:30:24-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:25 volumio volumio[30543]: info: MYVOLUMIO Environment detected Dec 09 15:30:25 volumio volumio[30543]: info: Plugin folders cleanup Dec 09 15:30:25 volumio volumio[30543]: info: Scanning into folder /volumio/app/plugins/ Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category audio_interface Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category miscellanea Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category music_service Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category plugins.json Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category system_controller Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category user_interface Dec 09 15:30:25 volumio go-librespot[30565]: time="2025-12-09T15:30:25-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:25 volumio volumio[30543]: info: Scanning into folder /data/plugins/ Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category audio_interface Dec 09 15:30:25 volumio go-librespot[30565]: time="2025-12-09T15:30:25-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:25 volumio go-librespot[30565]: time="2025-12-09T15:30:25-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category music_service Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category system_controller Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category system_hardware Dec 09 15:30:25 volumio volumio[30543]: info: Scanning category user_interface Dec 09 15:30:25 volumio volumio[30543]: info: Plugin folders cleanup completed Dec 09 15:30:25 volumio volumio[30543]: info: ------------------------------------------- Dec 09 15:30:25 volumio volumio[30543]: info: ----- Core plugins startup ---- Dec 09 15:30:25 volumio volumio[30543]: info: ------------------------------------------- Dec 09 15:30:25 volumio volumio[30543]: info: Loading plugins from folder /volumio/app/plugins/ Dec 09 15:30:25 volumio volumio[30543]: info: Adding plugin upnp to MyMusic Plugins Dec 09 15:30:25 volumio volumio[30543]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 09 15:30:25 volumio go-librespot[30565]: time="2025-12-09T15:30:25-06:00" level=info msg="zeroconf server listening on port 42239" Dec 09 15:30:25 volumio volumio[30543]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 09 15:30:25 volumio volumio[30543]: info: Loading plugins from folder /data/plugins/ Dec 09 15:30:25 volumio volumio[30543]: info: Loading plugin "system"... Dec 09 15:30:25 volumio volumio[30543]: info: Loading plugin "appearance"... Dec 09 15:30:25 volumio go-librespot[30565]: time="2025-12-09T15:30:25-06:00" level=debug msg="obtained new client token: AACs6qxBthVb+TEE6WWNzI5V7mC6mFCLvnGJV953bmVu8kgH2wU2Z0kN65VFOef/w+oWdScqHKeS8TLzYnFH9AKbPD/99exun3BWB6iPje2/Z9BD+e4UCslt3gi3V+n09dk+EFs/X8vtfB+IKcd/FxAF59vFs0CakcJZi8dpg0USVr3jqwMDuMe6nXBCPEMLMD7L+Fx5LN4djUffSF/k9KW1dLczvUBjFXEG0uW/9srQiUqizXRFjW/ZrQ==" Dec 09 15:30:25 volumio go-librespot[30565]: time="2025-12-09T15:30:25-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:26 volumio go-librespot[30565]: time="2025-12-09T15:30:26-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:26 volumio go-librespot[30565]: time="2025-12-09T15:30:26-06:00" level=debug msg="completed challenge" Dec 09 15:30:26 volumio go-librespot[30565]: time="2025-12-09T15:30:26-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:26 volumio volumio[30543]: info: Loading plugin "network"... Dec 09 15:30:26 volumio volumio[30543]: info: Refreshing Cached IP Addresses Dec 09 15:30:26 volumio sudo[30580]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 09 15:30:26 volumio sudo[30580]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:26 volumio sudo[30582]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 09 15:30:26 volumio sudo[30582]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:26 volumio sudo[30580]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:26 volumio volumio[30543]: info: Loading plugin "services"... Dec 09 15:30:26 volumio sudo[30582]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:26 volumio volumio[30543]: info: Loading plugin "alsa_controller"... Dec 09 15:30:26 volumio sudo[30589]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 09 15:30:26 volumio sudo[30589]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:26 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 15:30:26 volumio volumio[30543]: info: Loading plugin "wizard"... Dec 09 15:30:26 volumio volumio[30543]: info: Loading plugin "networkfs"... Dec 09 15:30:26 volumio volumio[30543]: info: Starting Udev Watcher for removable devices Dec 09 15:30:26 volumio volumio[30543]: info: Ignoring mount for partition: boot Dec 09 15:30:26 volumio volumio[30543]: info: Ignoring mount for partition: volumio Dec 09 15:30:26 volumio volumio[30543]: info: Ignoring mount for partition: volumio_data Dec 09 15:30:26 volumio volumio[30543]: info: Mounting Device Wikipedia Dec 09 15:30:26 volumio sudo[30619]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 09 15:30:26 volumio sudo[30619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:26 volumio sudo[30619]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:27 volumio volumio[30543]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 09 15:30:27 volumio volumio[30543]: dmesg(1) may have more information after failed mount system call. Dec 09 15:30:27 volumio volumio[30543]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 09 15:30:27 volumio volumio[30543]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 09 15:30:27 volumio volumio[30543]: dmesg(1) may have more information after failed mount system call. Dec 09 15:30:27 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 15:30:27 volumio volumio[30543]: info: Loading plugin "volumio_command_line_client"... Dec 09 15:30:27 volumio volumio[30543]: info: Loading plugin "upnp"... Dec 09 15:30:27 volumio volumio[30543]: info: [1765315827016] Starting Upmpd Daemon Dec 09 15:30:27 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 15:30:27 volumio volumio[30543]: info: Loading plugin "my_music"... Dec 09 15:30:27 volumio volumio[30543]: info: Loading plugin "mpd"... Dec 09 15:30:27 volumio volumio-remote-updater[9752]: [2025-12-09 15:30:27] [connect] Successful connection Dec 09 15:30:27 volumio sudo[30589]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:27 volumio volumio[30543]: info: Loading plugin "upnp_browser"... Dec 09 15:30:28 volumio volumio[30543]: info: Loading plugin "alarm-clock"... Dec 09 15:30:28 volumio volumio[30543]: info: Loading plugin "airplay_emulation"... Dec 09 15:30:29 volumio volumio[30543]: info: Starting Shairport Sync Dec 09 15:30:29 volumio volumio[30543]: info: Loading plugin "last_100"... Dec 09 15:30:29 volumio volumio[30543]: info: Loading plugin "webradio"... Dec 09 15:30:29 volumio volumio[30543]: info: Loading plugin "i2s_dacs"... Dec 09 15:30:29 volumio volumio[30543]: info: I2S DAC not set, start Auto-detection Dec 09 15:30:29 volumio volumio[30543]: info: Loading plugin "volumiodiscovery"... Dec 09 15:30:29 volumio volumio[30543]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 09 15:30:29 volumio volumio[30543]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 15:30:29 volumio volumio[30543]: *** WARNING *** For more information see Dec 09 15:30:29 volumio volumio[30543]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 09 15:30:29 volumio volumio[30543]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 15:30:29 volumio volumio[30543]: *** WARNING *** For more information see Dec 09 15:30:29 volumio node[30543]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 09 15:30:29 volumio node[30543]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 15:30:29 volumio node[30543]: *** WARNING *** For more information see Dec 09 15:30:29 volumio node[30543]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 09 15:30:29 volumio node[30543]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 15:30:29 volumio node[30543]: *** WARNING *** For more information see Dec 09 15:30:29 volumio volumio[30543]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 09 15:30:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 163. Dec 09 15:30:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:29 volumio volumio[30543]: info: Discovery: Started advertising with name: Volumio Dec 09 15:30:29 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 15:30:29 volumio volumio[30543]: info: Loading plugin "bandcamp"... Dec 09 15:30:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:29 volumio go-librespot[30622]: go-librespot daemon starting... Dec 09 15:30:29 volumio go-librespot[30624]: time="2025-12-09T15:30:29-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:29 volumio go-librespot[30624]: time="2025-12-09T15:30:29-06:00" level=debug msg="app state loaded" Dec 09 15:30:29 volumio go-librespot[30624]: time="2025-12-09T15:30:29-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:29 volumio go-librespot[30624]: time="2025-12-09T15:30:29-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:29 volumio go-librespot[30624]: time="2025-12-09T15:30:29-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:29 volumio go-librespot[30624]: time="2025-12-09T15:30:29-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:29 volumio go-librespot[30624]: time="2025-12-09T15:30:29-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:29 volumio go-librespot[30624]: time="2025-12-09T15:30:29-06:00" level=info msg="zeroconf server listening on port 33221" Dec 09 15:30:29 volumio go-librespot[30624]: time="2025-12-09T15:30:29-06:00" level=debug msg="obtained new client token: AAAjIFn8J/g0hVEK6JTkmga0cBbONEfm7MLzxH4XVASZT4OCN5NRwlzcrLCvYLSSWgZHawLrE8lKFjJurbvoy/v1x/OxWTdDXBl9jDqih1kT8+ENXCuyN+OSlHSciVTGRBwDMy54I9c5eOZLP3TH8hQhM4tDzzSORL2XpYXRO0whJNRYxmKPFVrx9AWeIRjZz/36lFcWDfMZiJkvb9bNq9UMlgrnqUMN7tADrus2iKIcd2e8f0KbMOwI1Q==" Dec 09 15:30:30 volumio go-librespot[30624]: time="2025-12-09T15:30:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:30 volumio go-librespot[30624]: time="2025-12-09T15:30:30-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:30 volumio go-librespot[30624]: time="2025-12-09T15:30:30-06:00" level=debug msg="completed challenge" Dec 09 15:30:30 volumio go-librespot[30624]: time="2025-12-09T15:30:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:30 volumio volumio[30543]: info: Plugin calmradio is not enabled Dec 09 15:30:30 volumio volumio[30543]: info: Loading plugin "soundcloud"... Dec 09 15:30:30 volumio volumio[30543]: info: Loading plugin "spop"... Dec 09 15:30:31 volumio volumio[30543]: info: Loading plugin "squeezelite_mc"... Dec 09 15:30:32 volumio volumio[30543]: info: Loading plugin "youtube2"... Dec 09 15:30:33 volumio volumio[30543]: info: Loading plugin "ytcr"... Dec 09 15:30:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 164. Dec 09 15:30:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:33 volumio go-librespot[30631]: go-librespot daemon starting... Dec 09 15:30:33 volumio go-librespot[30632]: time="2025-12-09T15:30:33-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:33 volumio go-librespot[30632]: time="2025-12-09T15:30:33-06:00" level=debug msg="app state loaded" Dec 09 15:30:33 volumio go-librespot[30632]: time="2025-12-09T15:30:33-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:33 volumio go-librespot[30632]: time="2025-12-09T15:30:33-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:34 volumio go-librespot[30632]: time="2025-12-09T15:30:34-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:34 volumio go-librespot[30632]: time="2025-12-09T15:30:34-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:34 volumio go-librespot[30632]: time="2025-12-09T15:30:34-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:34 volumio go-librespot[30632]: time="2025-12-09T15:30:34-06:00" level=info msg="zeroconf server listening on port 46395" Dec 09 15:30:34 volumio go-librespot[30632]: time="2025-12-09T15:30:34-06:00" level=debug msg="obtained new client token: AAC04cZrhJfpm3UqpAaqArwA26lM2KWMeM2v7BdhYwC4trSfv9dJso6N4d4I5FLKhV0U0zCNKIFYtQOWfJ/JOcAfr6ZpT6AT7nDyFUGLD+vad/o4qNMGpgS/ka/FFmmJzAZ3tptlWAlOzK0s11Lajcy8pU0n8sE3quXvqWt/OHYtHyKmPbSLYBnfBDMqv5o2PWdWthe16EKzf5O6mOoANy7fhVz7LYOBTWsmKKq3SLiXDbJeeU07CbyDRw==" Dec 09 15:30:34 volumio volumio[30543]: info: Loading plugin "ytmusic"... Dec 09 15:30:34 volumio go-librespot[30632]: time="2025-12-09T15:30:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:34 volumio go-librespot[30632]: time="2025-12-09T15:30:34-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:34 volumio go-librespot[30632]: time="2025-12-09T15:30:34-06:00" level=debug msg="completed challenge" Dec 09 15:30:34 volumio go-librespot[30632]: time="2025-12-09T15:30:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:35 volumio volumio[30543]: info: Plugin now_playing is not enabled Dec 09 15:30:35 volumio volumio[30543]: info: Loading plugin "outputs"... Dec 09 15:30:35 volumio volumio[30543]: info: Loading plugin "albumart"... Dec 09 15:30:35 volumio volumio[30543]: info: Plugin example_plugin is not enabled Dec 09 15:30:35 volumio volumio[30543]: info: Loading plugin "inputs"... Dec 09 15:30:35 volumio volumio[30543]: info: Loading plugin "updater_comm"... Dec 09 15:30:35 volumio volumio[30543]: info: Plugin mpdemulation is not enabled Dec 09 15:30:35 volumio volumio[30543]: info: Loading plugin "rest_api"... Dec 09 15:30:35 volumio volumio[30543]: info: Loading plugin "websocket"... Dec 09 15:30:35 volumio volumio[30543]: info: Starting Socket.io Server version 1.7.4 Dec 09 15:30:35 volumio volumio[30543]: info: Plugin fusiondsp is not enabled Dec 09 15:30:35 volumio volumio[30543]: info: Plugin mpdoutput is not enabled Dec 09 15:30:35 volumio volumio[30543]: info: Plugin RoonBridge is not enabled Dec 09 15:30:35 volumio volumio[30543]: info: Loading plugin "podcast"... Dec 09 15:30:35 volumio volumio[30543]: info: ControllerPodcast::constructor Dec 09 15:30:35 volumio volumio[30543]: info: Loading plugin "volusonic"... Dec 09 15:30:35 volumio volumio[30640]: Forking 3 albumart workers Dec 09 15:30:37 volumio volumio[30543]: info: Applying required configuration parameters for plugin volusonic Dec 09 15:30:37 volumio volumio[30543]: info: Loading plugin "backup_restore"... Dec 09 15:30:37 volumio volumio[30650]: Starting albumart workers Dec 09 15:30:37 volumio volumio[30651]: Starting albumart workers Dec 09 15:30:37 volumio volumio[30652]: Starting albumart workers Dec 09 15:30:37 volumio volumio[30543]: info: Applying required configuration parameters for plugin backup_restore Dec 09 15:30:37 volumio volumio[30543]: info: Plugin rpi_eeprom_config is not enabled Dec 09 15:30:37 volumio volumio[30543]: info: Plugin rpi_eeprom_updater is not enabled Dec 09 15:30:37 volumio volumio[30543]: info: Loading plugin "scheduledrestart"... Dec 09 15:30:37 volumio volumio[30543]: info: Applying required configuration parameters for plugin scheduledrestart Dec 09 15:30:37 volumio volumio[30543]: info: Plugin Bluetoothremote is not enabled Dec 09 15:30:37 volumio volumio[30543]: info: Plugin music_services_shield is not enabled Dec 09 15:30:37 volumio volumio[30543]: info: Loading plugin "Systeminfo"... Dec 09 15:30:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 165. Dec 09 15:30:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:38 volumio go-librespot[30703]: go-librespot daemon starting... Dec 09 15:30:38 volumio go-librespot[30704]: time="2025-12-09T15:30:38-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:38 volumio go-librespot[30704]: time="2025-12-09T15:30:38-06:00" level=debug msg="app state loaded" Dec 09 15:30:38 volumio go-librespot[30704]: time="2025-12-09T15:30:38-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:38 volumio go-librespot[30704]: time="2025-12-09T15:30:38-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:38 volumio volumio[30543]: info: Plugin peppymeterbasic is not enabled Dec 09 15:30:38 volumio volumio[30543]: info: Loading plugin "peppyspectrum"... Dec 09 15:30:38 volumio volumio[30543]: info: Loading i18n strings for locale en Dec 09 15:30:38 volumio volumio[30543]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 09 15:30:38 volumio volumio[30543]: Updating browse sources language Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:38 volumio go-librespot[30704]: time="2025-12-09T15:30:38-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:38 volumio go-librespot[30704]: time="2025-12-09T15:30:38-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:38 volumio go-librespot[30704]: time="2025-12-09T15:30:38-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:38 volumio go-librespot[30704]: time="2025-12-09T15:30:38-06:00" level=info msg="zeroconf server listening on port 38429" Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::initPlayerControls Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 15:30:38 volumio volumio[30543]: Express server listening on port 3000 Dec 09 15:30:38 volumio volumio[30543]: [Metrics] WebUI: 14s 537.51ms Dec 09 15:30:38 volumio volumio[30543]: info: CoreStateMachine::resetVolumioState Dec 09 15:30:38 volumio volumio[30543]: info: CoreStateMachine::getcurrentVolume Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::volumioRetrievevolume Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:30:38 volumio sudo[30728]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 09 15:30:38 volumio sudo[30728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:38 volumio sudo[30730]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 09 15:30:38 volumio sudo[30730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:38 volumio sudo[30728]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:38 volumio go-librespot[30704]: time="2025-12-09T15:30:38-06:00" level=debug msg="obtained new client token: AAD+XJql+3Y5PpBMklk7zhSBXXYxuMUAWS8O9md7xYKrFJciIHcQdEGAwhTeiHlZfKDAEzme31s4SfbZgLvCroUZcwCgkELOE5s8LNxY7bvDHJUNzlFRAX9BkTWwcymQX17JrsTSst3Pv5AcmgQRrwIPNOJKu4BmQarRbEpj74qdRsHaOI9cj+ZZON1UsAAxnJFF2Ww0YCAm7QPy1nkDTbbPuIlv8/WaOJvk/ubXIhyRTUCsa8St/24ODA==" Dec 09 15:30:38 volumio sudo[30730]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:38 volumio volumio[30543]: info: Volumio Network Manager: Network status updated: 1 Dec 09 15:30:38 volumio volumio[30543]: info: VolumeController:: Volume=86 Mute =false Dec 09 15:30:38 volumio volumio[30543]: info: CoreStateMachine::pushState Dec 09 15:30:38 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::volumioPushState Dec 09 15:30:38 volumio volumio[30543]: info: CoreStateMachine::updateTrackBlock Dec 09 15:30:38 volumio volumio[30543]: info: CorePlayQueue::getTrackBlock Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::volumioRetrievevolume Dec 09 15:30:38 volumio go-librespot[30704]: time="2025-12-09T15:30:38-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:38 volumio volumio[30543]: info: Reloading queue from file Dec 09 15:30:38 volumio volumio[30543]: info: CoreStateMachine::setRepeat null single undefined Dec 09 15:30:38 volumio volumio[30543]: info: CoreStateMachine::pushState Dec 09 15:30:38 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:38 volumio volumio[30543]: info: CoreCommandRouter::volumioPushState Dec 09 15:30:39 volumio volumio[30543]: info: CoreStateMachine::setRandom null Dec 09 15:30:39 volumio volumio[30543]: info: CoreStateMachine::pushState Dec 09 15:30:39 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioPushState Dec 09 15:30:39 volumio volumio[30543]: info: Setting Device type: Raspberry PI Dec 09 15:30:39 volumio go-librespot[30704]: time="2025-12-09T15:30:39-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:39 volumio go-librespot[30704]: time="2025-12-09T15:30:39-06:00" level=debug msg="completed challenge" Dec 09 15:30:39 volumio volumio[30543]: info: VolumeController:: Volume=86 Mute =false Dec 09 15:30:39 volumio volumio[30543]: info: CoreStateMachine::pushState Dec 09 15:30:39 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioPushState Dec 09 15:30:39 volumio volumio[30543]: info: Completed loading Core Plugins Dec 09 15:30:39 volumio volumio[30543]: info: Preparing to generate the ALSA configuration file Dec 09 15:30:39 volumio sudo[30743]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 09 15:30:39 volumio go-librespot[30704]: time="2025-12-09T15:30:39-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:39 volumio sudo[30743]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:39 volumio volumio[30543]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 09 15:30:39 volumio volumio[30543]: info: Reading ALSA contributions from plugins. Dec 09 15:30:39 volumio volumio[30543]: info: Asound.conf file unchanged, so no further update is needed Dec 09 15:30:39 volumio sudo[30743]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:39 volumio volumio[30543]: info: Output device has changed, restarting MPD Dec 09 15:30:39 volumio volumio[30543]: info: Output device has changed, restarting Shairport Sync Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:30:39 volumio sudo[30746]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 15:30:39 volumio sudo[30746]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:39 volumio sudo[30746]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:39 volumio sudo[30748]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 15:30:39 volumio sudo[30748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:39 volumio volumio[30543]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 15:30:39 volumio volumio[30543]: info: ___________ START PLUGINS ___________ Dec 09 15:30:39 volumio volumio[30543]: info: ControllerMpd::onStart: Initializing MPD Dec 09 15:30:39 volumio volumio[30543]: info: Creating MPD Configuration file Dec 09 15:30:39 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 09 15:30:39 volumio sudo[30756]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:30:39 volumio volumio[30543]: info: [1765315839272] CoreMusicLibrary::Adding element Media Servers Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:39 volumio sudo[30756]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:39 volumio sudo[30756]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:39 volumio sudo[30758]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 15:30:39 volumio sudo[30758]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:30:39 volumio volumio[30543]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 15:30:39 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:30:39 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 15:30:39 volumio systemd[1]: mpd.service: Consumed 4.520s CPU time. Dec 09 15:30:39 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 09 15:30:39 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 15:30:39 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 15:30:39 volumio volumio[30543]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:30:39 volumio volumio[30543]: info: [1765315839376] CoreMusicLibrary::Adding element Last_100 Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:30:39 volumio volumio[30543]: info: [1765315839380] CoreMusicLibrary::Adding element Webradio Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 15:30:39 volumio volumio[30543]: info: Initializing BBC Radios Dec 09 15:30:39 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 15:30:39 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 15:30:39 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 09 15:30:39 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 15:30:39 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 09 15:30:39 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 15:30:39 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 15:30:39 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:30:39 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:30:39 volumio volumio[30543]: info: [1765315839472] CoreMusicLibrary::Adding element Bandcamp Discover Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Bandcamp Discover Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:30:39 volumio volumio[30543]: info: [1765315839484] CoreMusicLibrary::Adding element SoundCloud Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Bandcamp Discover Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source SoundCloud Dec 09 15:30:39 volumio volumio[30543]: info: Creating Spotify config file Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:39 volumio sudo[30785]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 09 15:30:39 volumio sudo[30785]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 09 15:30:39 volumio sudo[30785]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:39 volumio volumio-remote-updater[9752]: [2025-12-09 15:30:39] [connect] Successful connection Dec 09 15:30:39 volumio volumio[30543]: info: [squeezelite_mc] Starting proxy server... Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:30:39 volumio volumio[30543]: info: [1765315839846] CoreMusicLibrary::Adding element YouTube2 Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Bandcamp Discover Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source SoundCloud Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube2 Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:30:39 volumio volumio[30543]: info: [1765315839865] CoreMusicLibrary::Adding element YouTube Music Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Bandcamp Discover Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source SoundCloud Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube2 Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube Music Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:30:39 volumio volumio[30543]: info: [1765315839876] CoreMusicLibrary::Adding element Podcast Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Bandcamp Discover Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source SoundCloud Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube2 Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube Music Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Podcast Dec 09 15:30:39 volumio volumio[30543]: info: Loading i18n strings for locale en Dec 09 15:30:39 volumio volumio[30543]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 09 15:30:39 volumio volumio[30543]: Updating browse sources language Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Bandcamp Discover Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source SoundCloud Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube2 Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube Music Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Podcast Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Bandcamp Discover Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source SoundCloud Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube2 Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube Music Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Podcast Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:30:39 volumio volumio[30543]: info: [1765315839925] CoreMusicLibrary::Adding element Volusonic Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Bandcamp Discover Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source SoundCloud Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube2 Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source YouTube Music Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Podcast Dec 09 15:30:39 volumio volumio[30543]: Cannot find translation for source Volusonic Dec 09 15:30:39 volumio volumio[30543]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 09 15:30:39 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 09 15:30:39 volumio volumio[30543]: info: Volumio Calling Home Dec 09 15:30:40 volumio volumio[30543]: info: [squeezelite_mc] Proxy server started on port 38571 Dec 09 15:30:40 volumio volumio[30543]: info: Preparing to generate the ALSA configuration file Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::volumioRetrievevolume Dec 09 15:30:40 volumio volumio[30543]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 09 15:30:40 volumio volumio[30543]: info: Discovery: Found device Volumio Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::volumioGetState Dec 09 15:30:40 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:40 volumio volumio[30543]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 09 15:30:40 volumio volumio[30543]: info: Discovery: Found device Volumio Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::volumioGetState Dec 09 15:30:40 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:40 volumio volumio[30543]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 09 15:30:40 volumio volumio[30543]: info: Reading ALSA contributions from plugins. Dec 09 15:30:40 volumio volumio[30543]: info: MPD Permissions set Dec 09 15:30:40 volumio volumio[30543]: info: MPD Permissions set Dec 09 15:30:40 volumio volumio[30543]: info: Upmpdcli Daemon Started Dec 09 15:30:40 volumio volumio-remote-updater[9752]: [2025-12-09 15:30:40] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765315839 101 Dec 09 15:30:40 volumio volumio[30543]: 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 Dec 09 15:30:40 volumio volumio[30543]: info: Spotify config file written Dec 09 15:30:40 volumio sudo[30795]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 09 15:30:40 volumio sudo[30795]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:40 volumio volumio[30543]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 09 15:30:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:40 volumio volumio[30543]: info: VolumeController:: Volume=86 Mute =false Dec 09 15:30:40 volumio volumio[30543]: info: CoreStateMachine::pushState Dec 09 15:30:40 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::volumioPushState Dec 09 15:30:40 volumio volumio[30543]: info: [squeezelite_mc] Server discovery started Dec 09 15:30:40 volumio volumio[30543]: info: [squeezelite_mc] Player finder started Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio go-librespot[30797]: go-librespot daemon starting... Dec 09 15:30:40 volumio sudo[30795]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio go-librespot[30801]: time="2025-12-09T15:30:40-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:40 volumio go-librespot[30801]: time="2025-12-09T15:30:40-06:00" level=debug msg="app state loaded" Dec 09 15:30:40 volumio go-librespot[30801]: time="2025-12-09T15:30:40-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:40 volumio go-librespot[30801]: time="2025-12-09T15:30:40-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:40 volumio volumio[30543]: info: No need to fix Spotify hosts Dec 09 15:30:40 volumio volumio[30543]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 09 15:30:40 volumio volumio[30543]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 09 15:30:40 volumio volumio[30543]: SPOTIFY: BQBLTG1emJDrVRRsF17S_kqmieFMAYHHm9IkjtrD9NmW8E94u4pgI8sHohjud0BwBSo9HtqS9phvjkHo3LTzs_bwIOVgk0Tgv6jcdhohhJdyW8LUBc3nPPZYIzoL86a4ilJjqVv0EAJX1a9u011SRtwefxksOEajDZbFu9nK0Javy1ELlCulaSMlwWdChIHgAzY3bPjb6kF9-o0WDhgxNGTbVygmnDM7JDQYLyc Dec 09 15:30:40 volumio volumio[30543]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 09 15:30:40 volumio volumio[30543]: info: New Spotify access token = BQBLTG1emJDrVRRsF17S_kqmieFMAYHHm9IkjtrD9NmW8E94u4pgI8sHohjud0BwBSo9HtqS9phvjkHo3LTzs_bwIOVgk0Tgv6jcdhohhJdyW8LUBc3nPPZYIzoL86a4ilJjqVv0EAJX1a9u011SRtwefxksOEajDZbFu9nK0Javy1ELlCulaSMlwWdChIHgAzY3bPjb6kF9-o0WDhgxNGTbVygmnDM7JDQYLyc Dec 09 15:30:40 volumio volumio[30543]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 09 15:30:40 volumio volumio[30543]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"} Dec 09 15:30:40 volumio volumio[30543]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 09 15:30:40 volumio volumio[30543]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 09 15:30:40 volumio volumio[30543]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 09 15:30:40 volumio sudo[30818]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 09 15:30:40 volumio sudo[30818]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:40 volumio volumio[30543]: info: Starting Shairport Sync Dec 09 15:30:40 volumio sudo[30818]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:40 volumio volumio[30543]: info: Starting Shairport Sync Dec 09 15:30:40 volumio volumio[30543]: info: Starting Shairport Sync Dec 09 15:30:40 volumio sudo[30824]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 15:30:40 volumio sudo[30824]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:40 volumio sudo[30827]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 15:30:40 volumio sudo[30827]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:40 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 09 15:30:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 09 15:30:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 15:30:41 volumio systemd[1]: shairport-sync.service: Consumed 2.164s CPU time. Dec 09 15:30:41 volumio sudo[30828]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 15:30:41 volumio sudo[30828]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:41 volumio go-librespot[30801]: time="2025-12-09T15:30:41-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 09 15:30:41 volumio go-librespot[30801]: time="2025-12-09T15:30:41-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 09 15:30:41 volumio go-librespot[30801]: time="2025-12-09T15:30:41-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 09 15:30:41 volumio go-librespot[30801]: time="2025-12-09T15:30:41-06:00" level=info msg="zeroconf server listening on port 44611" Dec 09 15:30:41 volumio volumio[30543]: info: Volumio called home Dec 09 15:30:41 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 15:30:41 volumio sudo[30824]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:41 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 09 15:30:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 09 15:30:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 15:30:41 volumio go-librespot[30801]: time="2025-12-09T15:30:41-06:00" level=debug msg="obtained new client token: AAAtMrzZelrHTqzlgw34VSRzA5Wbaot8Ck+l7OTzYbIZseSBCoZ+2HoESYstfetozjhoWpEl5P+ydA30s7dM44LkHHo/IMnVNAwhtWD/Ycx/a0nZggx94KMPUvA8HXtK6xrKu4kFej6eDhSmi2SgbfMtfhODDp/NyhpYksOivEWK22XRDkxwj5U+F5eTQNnuJVFxp0cSkI4XYhrQzRYCmIaQJ3RbEwtH6Z0Q6/8riboz9wDuJTQ7eMw=" Dec 09 15:30:41 volumio volumio[30543]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 09 15:30:41 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 15:30:41 volumio sudo[30827]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:41 volumio volumio[30543]: info: Asound.conf file unchanged, so no further update is needed Dec 09 15:30:41 volumio volumio[30543]: info: Output device has changed, restarting MPD Dec 09 15:30:41 volumio sudo[30828]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:41 volumio volumio[30543]: info: Output device has changed, restarting Shairport Sync Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:30:41 volumio sudo[30842]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 15:30:41 volumio sudo[30842]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:41 volumio volumio[30543]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 15:30:41 volumio sudo[30837]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 09 15:30:41 volumio sudo[30837]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:41 volumio sudo[30840]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 15:30:41 volumio sudo[30837]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:41 volumio sudo[30840]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:41 volumio go-librespot[30801]: time="2025-12-09T15:30:41-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:41 volumio sudo[30840]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:41 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 09 15:30:41 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 15:30:41 volumio systemd[1]: mpd.service: Consumed 1.772s CPU time. Dec 09 15:30:41 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 09 15:30:41 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 15:30:41 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 15:30:41 volumio go-librespot[30801]: time="2025-12-09T15:30:41-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:41 volumio go-librespot[30801]: time="2025-12-09T15:30:41-06:00" level=debug msg="completed challenge" Dec 09 15:30:41 volumio volumio[30543]: info: Shairport-Sync Started Dec 09 15:30:41 volumio volumio[30543]: Error adding Membership: Error: addMembership EINVAL Dec 09 15:30:41 volumio go-librespot[30801]: time="2025-12-09T15:30:41-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:41 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 15:30:41 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 15:30:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:41 volumio volumio[30543]: info: MPD Permissions set Dec 09 15:30:41 volumio volumio[30543]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 09 15:30:41 volumio volumio[30543]: info: Shairport-Sync Started Dec 09 15:30:41 volumio volumio[30543]: info: Shairport-Sync Started Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::volumioGetState Dec 09 15:30:41 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:41 volumio sudo[30871]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 09 15:30:41 volumio sudo[30871]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:41 volumio sudo[30871]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:41 volumio volumio[30543]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Dec 09 15:30:41 volumio volumio[30543]: info: Spotify Successfully logged in Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:30:41 volumio volumio[30543]: info: [1765315841776] CoreMusicLibrary::Adding element Spotify Dec 09 15:30:41 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:30:41 volumio volumio[30543]: Cannot find translation for source Bandcamp Discover Dec 09 15:30:41 volumio volumio[30543]: Cannot find translation for source SoundCloud Dec 09 15:30:41 volumio volumio[30543]: Cannot find translation for source YouTube2 Dec 09 15:30:41 volumio volumio[30543]: Cannot find translation for source YouTube Music Dec 09 15:30:41 volumio volumio[30543]: Cannot find translation for source Podcast Dec 09 15:30:41 volumio volumio[30543]: Cannot find translation for source Volusonic Dec 09 15:30:41 volumio volumio[30543]: Cannot find translation for source Spotify Dec 09 15:30:41 volumio sudo[30868]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 09 15:30:41 volumio sudo[30868]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 09 15:30:41 volumio sudo[30868]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:41 volumio volumio[30543]: info: Starting Shairport Sync Dec 09 15:30:41 volumio volumio[30543]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 09 15:30:41 volumio sudo[30880]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 15:30:41 volumio sudo[30880]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:41 volumio sudo[30883]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 09 15:30:41 volumio sudo[30883]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:41 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 09 15:30:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 09 15:30:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 15:30:41 volumio systemd[1]: Reloading. Dec 09 15:30:42 volumio volumio[30543]: info: [squeezelite_mc] Notification listener started Dec 09 15:30:42 volumio volumio[30543]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 09 15:30:42 volumio volumio[30543]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 09 15:30:42 volumio volumio[30543]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 09 15:30:42 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:42 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:42 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:30:42 volumio volumio[30543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 15:30:43 volumio volumio[30543]: info: CoreCommandRouter::volumioGetState Dec 09 15:30:43 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:43 volumio volumio[30543]: info: go-librespot daemon successfully initialized Dec 09 15:30:43 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 09 15:30:43 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 09 15:30:43 volumio sudo[30883]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:43 volumio volumio[30543]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:30:43 volumio sudo[30905]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:30:43 volumio sudo[30905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:44 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 15:30:44 volumio sudo[30880]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:44 volumio volumio[30543]: info: Shairport-Sync Started Dec 09 15:30:44 volumio sudo[30905]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:44 volumio volumio[30543]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 09 15:30:44 volumio sudo[30922]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 09 15:30:44 volumio sudo[30922]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:44 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 09 15:30:44 volumio volumio[30543]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect' Dec 09 15:30:44 volumio volumio[30543]: info: CoreCommandRouter::volumioGetState Dec 09 15:30:44 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:44 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 09 15:30:44 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 09 15:30:44 volumio sudo[30922]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 166. Dec 09 15:30:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:44 volumio go-librespot[30924]: go-librespot daemon starting... Dec 09 15:30:44 volumio go-librespot[30925]: time="2025-12-09T15:30:44-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:44 volumio go-librespot[30925]: time="2025-12-09T15:30:44-06:00" level=debug msg="app state loaded" Dec 09 15:30:44 volumio go-librespot[30925]: time="2025-12-09T15:30:44-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:44 volumio go-librespot[30925]: time="2025-12-09T15:30:44-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:45 volumio volumio[30543]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:30:45 volumio sudo[30933]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:30:45 volumio sudo[30933]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:45 volumio go-librespot[30925]: time="2025-12-09T15:30:45-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:45 volumio go-librespot[30925]: time="2025-12-09T15:30:45-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:45 volumio go-librespot[30925]: time="2025-12-09T15:30:45-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:45 volumio go-librespot[30925]: time="2025-12-09T15:30:45-06:00" level=info msg="zeroconf server listening on port 34331" Dec 09 15:30:45 volumio sudo[30933]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:45 volumio volumio[30543]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 09 15:30:45 volumio sudo[30937]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 09 15:30:45 volumio sudo[30937]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:45 volumio sudo[30937]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:45 volumio volumio[30543]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 09 15:30:45 volumio sudo[30940]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 09 15:30:45 volumio sudo[30940]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:45 volumio go-librespot[30925]: time="2025-12-09T15:30:45-06:00" level=debug msg="obtained new client token: AACwoq+Jmv0e0tI0qcODk51wSNhIgrrsKEkfpp6h/X3UZo830SoLSdhmzEpwrbVkYGhFZaGWCeNPqWTIOxf9Mk2orDa+3RNayUNQiuNKjv92edd0QKTjtUTPH4lMJvLj2HLXp2lP1/gdlo0zRfBH+RVja+NIprU1Ce7HBhkG4yg8tgpBmlDI2EEdUgoM5MBxpZBasjesbxJ/VJqMhSuEZnIkiba02NQ5MHqhMnrptkNv7uyp3cTF1TX9nw==" Dec 09 15:30:45 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 09 15:30:45 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 09 15:30:45 volumio sudo[30940]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:45 volumio go-librespot[30925]: time="2025-12-09T15:30:45-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:45 volumio mpd[30881]: 2025-12-09T15:30:45 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 09 15:30:45 volumio volumio[30543]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect' Dec 09 15:30:45 volumio volumio[30543]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 09 15:30:45 volumio go-librespot[30925]: time="2025-12-09T15:30:45-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:45 volumio go-librespot[30925]: time="2025-12-09T15:30:45-06:00" level=debug msg="completed challenge" Dec 09 15:30:45 volumio volumio[30543]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 09 15:30:45 volumio volumio[30543]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 09 15:30:45 volumio go-librespot[30925]: time="2025-12-09T15:30:45-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:45 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 09 15:30:45 volumio sudo[30842]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:45 volumio sudo[30748]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:45 volumio sudo[30758]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:45 volumio volumio[30543]: error: MPD error: The expression evaluated to a falsy value: Dec 09 15:30:45 volumio volumio[30543]: assert.ok(self.idling) Dec 09 15:30:45 volumio volumio[30543]: error: The expression evaluated to a falsy value: Dec 09 15:30:45 volumio volumio[30543]: assert.ok(self.idling) Dec 09 15:30:45 volumio volumio[30543]: error: MPD error: The expression evaluated to a falsy value: Dec 09 15:30:45 volumio volumio[30543]: assert.ok(self.idling) Dec 09 15:30:45 volumio volumio[30543]: error: The expression evaluated to a falsy value: Dec 09 15:30:45 volumio volumio[30543]: assert.ok(self.idling) Dec 09 15:30:45 volumio volumio[30543]: error: updateQueue error: null Dec 09 15:30:45 volumio volumio[30543]: info: MPD running with PID30881 Dec 09 15:30:45 volumio volumio[30543]: ,establishing connection Dec 09 15:30:45 volumio volumio[30543]: error: updateQueue error: null Dec 09 15:30:45 volumio volumio[30543]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:30:45 volumio sudo[30952]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:30:45 volumio sudo[30952]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:46 volumio sudo[30952]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:46 volumio volumio[30543]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:30:46 volumio sudo[30955]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:30:46 volumio sudo[30955]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:46 volumio sudo[30955]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:46 volumio volumio[30543]: info: CoreCommandRouter::volumioGetState Dec 09 15:30:46 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:46 volumio volumio[30543]: info: Initializing connection to go-librespot Websocket Dec 09 15:30:46 volumio volumio[30543]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 15:30:47 volumio volumio[30543]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:30:47 volumio sudo[30972]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:30:47 volumio sudo[30972]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:47 volumio sudo[30972]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:47 volumio volumio[30543]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:30:47 volumio sudo[30975]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:30:47 volumio sudo[30975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:47 volumio sudo[30975]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:48 volumio volumio[30543]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:30:48 volumio sudo[30978]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:30:48 volumio sudo[30978]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:48 volumio sudo[30978]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:48 volumio volumio[30543]: info: Completed starting Core Plugins Dec 09 15:30:48 volumio volumio[30543]: info: ------------------------------------------- Dec 09 15:30:48 volumio volumio[30543]: info: ----- MyVolumio plugins startup ---- Dec 09 15:30:48 volumio volumio[30543]: info: ------------------------------------------- Dec 09 15:30:48 volumio volumio[30543]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 09 15:30:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 167. Dec 09 15:30:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:48 volumio sudo[30982]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 15:30:48 volumio sudo[30982]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:48 volumio sudo[30984]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 15:30:48 volumio sudo[30984]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:48 volumio sudo[30986]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 15:30:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:48 volumio sudo[30986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:48 volumio go-librespot[30980]: go-librespot daemon starting... Dec 09 15:30:48 volumio go-librespot[30990]: time="2025-12-09T15:30:48-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:48 volumio go-librespot[30990]: time="2025-12-09T15:30:48-06:00" level=debug msg="app state loaded" Dec 09 15:30:48 volumio go-librespot[30990]: time="2025-12-09T15:30:48-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:48 volumio go-librespot[30990]: time="2025-12-09T15:30:48-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:48 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 09 15:30:48 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 09 15:30:48 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 09 15:30:48 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 09 15:30:48 volumio sudo[30982]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:48 volumio sudo[30984]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:48 volumio mpd_monitor.sh[30996]: MPD Monitor Service: Starting MPD Monitor Service Dec 09 15:30:48 volumio sudo[30986]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:48 volumio volumio[30543]: info: Successfully started MPD Monitor Dec 09 15:30:48 volumio volumio[30543]: info: Successfully started MPD Monitor Dec 09 15:30:48 volumio volumio[30543]: info: Successfully started MPD Monitor Dec 09 15:30:49 volumio go-librespot[30990]: time="2025-12-09T15:30:49-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:49 volumio go-librespot[30990]: time="2025-12-09T15:30:49-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:49 volumio go-librespot[30990]: time="2025-12-09T15:30:49-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:49 volumio go-librespot[30990]: time="2025-12-09T15:30:49-06:00" level=info msg="zeroconf server listening on port 42971" Dec 09 15:30:49 volumio volumio[30543]: info: Initializing connection to go-librespot Websocket Dec 09 15:30:49 volumio go-librespot[30990]: time="2025-12-09T15:30:49-06:00" level=debug msg="new websocket client" Dec 09 15:30:49 volumio volumio[30543]: info: Connection to go-librespot Websocket established Dec 09 15:30:49 volumio go-librespot[30990]: time="2025-12-09T15:30:49-06:00" level=debug msg="obtained new client token: AADEbhdPnvBQdw7B2RlPYRTCUuQwCAv6f92b4scT3b4DyTUY8A+6M32OHIZKy1x4ZFLZ8m4QLbSTJlyMm7ADti0M1QPKN3EUnoqInqM0zVOoK2eiq2LTdb2Otx2yTYFxzbERY49N6AeEMBB262qAaVpvCBNoEoSPazKBtJ24j8XZz9g7G6fHAGUbGtvxcmhtHaVQWt/n6vBGvDXdfKeCsCF4o0SIZmjMz0+PW7DIoAvpzRQ1+jfAXE87tg==" Dec 09 15:30:50 volumio go-librespot[30990]: time="2025-12-09T15:30:50-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:50 volumio go-librespot[30990]: time="2025-12-09T15:30:50-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:50 volumio go-librespot[30990]: time="2025-12-09T15:30:50-06:00" level=debug msg="completed challenge" Dec 09 15:30:50 volumio go-librespot[30990]: time="2025-12-09T15:30:50-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:50 volumio volumio[30543]: info: Connection to go-librespot Websocket closed Dec 09 15:30:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 168. Dec 09 15:30:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:53 volumio go-librespot[31002]: go-librespot daemon starting... Dec 09 15:30:53 volumio go-librespot[31003]: time="2025-12-09T15:30:53-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:53 volumio go-librespot[31003]: time="2025-12-09T15:30:53-06:00" level=debug msg="app state loaded" Dec 09 15:30:53 volumio go-librespot[31003]: time="2025-12-09T15:30:53-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:53 volumio volumio[30543]: info: Getting Spotify volume Dec 09 15:30:53 volumio go-librespot[31003]: time="2025-12-09T15:30:53-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:53 volumio volumio[30543]: info: Initializing connection to go-librespot Websocket Dec 09 15:30:53 volumio go-librespot[31003]: time="2025-12-09T15:30:53-06:00" level=debug msg="new websocket client" Dec 09 15:30:53 volumio volumio[30543]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 09 15:30:53 volumio volumio[30543]: info: Connection to go-librespot Websocket established Dec 09 15:30:53 volumio volumio[30543]: info: CoreCommandRouter::volumioGetState Dec 09 15:30:53 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:53 volumio volumio[30543]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 09 15:30:53 volumio volumio[30543]: SPOTIFY: SPOTIFY VOLUME undefined Dec 09 15:30:53 volumio volumio[30543]: SPOTIFY: VOLUMIO VOLUME 86 Dec 09 15:30:53 volumio volumio[30543]: info: Aligning Spotify Volume to Volumio Volume Dec 09 15:30:53 volumio volumio[30543]: info: CoreCommandRouter::volumioGetState Dec 09 15:30:53 volumio volumio[30543]: info: CorePlayQueue::getTrack 0 Dec 09 15:30:53 volumio volumio[30543]: info: Setting Spotify Volume from Volumio: 86 Dec 09 15:30:53 volumio go-librespot[31003]: time="2025-12-09T15:30:53-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:53 volumio go-librespot[31003]: time="2025-12-09T15:30:53-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:53 volumio go-librespot[31003]: time="2025-12-09T15:30:53-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:53 volumio go-librespot[31003]: time="2025-12-09T15:30:53-06:00" level=info msg="zeroconf server listening on port 42063" Dec 09 15:30:53 volumio go-librespot[31003]: time="2025-12-09T15:30:53-06:00" level=debug msg="obtained new client token: AABMH8PUlMRyRsXOJLKmvaAomMyPx5YvYdccWicN5yMQToFz33jK5H3ZhZnzxXg21rqWLGmvxmU46VNf1WrzIYAjFGcoBCR9RhILCsT8MBDG1cZjeGXXrD9HkMppFJEtfHcG8jTwYlxH61Cf1AWTD4W32JVlKUmYQKQiC23gohRmhOhaCYuQZ+XyNwVHo3rIibYr4P8pH5E5h1VmfEHRbOcXagP67Ba6qCg0/t6xT2Z6fSu7BAnCnxjFvQ==" Dec 09 15:30:54 volumio go-librespot[31003]: time="2025-12-09T15:30:54-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Dec 09 15:30:54 volumio go-librespot[31003]: time="2025-12-09T15:30:54-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Dec 09 15:30:54 volumio go-librespot[31003]: time="2025-12-09T15:30:54-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:54 volumio go-librespot[31003]: time="2025-12-09T15:30:54-06:00" level=debug msg="completed challenge" Dec 09 15:30:54 volumio go-librespot[31003]: time="2025-12-09T15:30:54-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:54 volumio volumio[30543]: info: Connection to go-librespot Websocket closed Dec 09 15:30:54 volumio volumio[30543]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 15:30:54 volumio volumio[30543]: Error: socket hang up Dec 09 15:30:54 volumio volumio[30543]: at connResetException (node:internal/errors:720:14) Dec 09 15:30:54 volumio volumio[30543]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 09 15:30:54 volumio volumio[30543]: at Socket.emit (node:events:526:35) Dec 09 15:30:54 volumio volumio[30543]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 09 15:30:54 volumio volumio[30543]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 09 15:30:54 volumio volumio[30543]: code: 'ECONNRESET', Dec 09 15:30:54 volumio volumio[30543]: response: undefined Dec 09 15:30:54 volumio volumio[30543]: } Dec 09 15:30:54 volumio volumio[30543]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 15:30:55 volumio sudo[31025]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 15:29' Dec 09 15:30:55 volumio sudo[31025]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:30:55 volumio sudo[31025]: pam_unix(sudo:session): session closed for user root Dec 09 15:30:56 volumio volumio-remote-updater[9752]: [2025-12-09 15:30:56] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 09 15:30:56 volumio volumio-remote-updater[9752]: [2025-12-09 15:30:56] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 09 15:30:56 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:56 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 09 15:30:56 volumio systemd[1]: volumio.service: Consumed 42.494s CPU time. Dec 09 15:30:56 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 09 15:30:56 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 09 15:30:56 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 24594. Dec 09 15:30:56 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 09 15:30:56 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 09 15:30:56 volumio systemd[1]: volumio.service: Consumed 42.494s CPU time. Dec 09 15:30:56 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 09 15:30:56 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 09 15:30:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 169. Dec 09 15:30:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:30:57 volumio go-librespot[31064]: go-librespot daemon starting... Dec 09 15:30:57 volumio go-librespot[31065]: time="2025-12-09T15:30:57-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:30:57 volumio go-librespot[31065]: time="2025-12-09T15:30:57-06:00" level=debug msg="app state loaded" Dec 09 15:30:57 volumio go-librespot[31065]: time="2025-12-09T15:30:57-06:00" level=debug msg="stored credentials not found" Dec 09 15:30:57 volumio go-librespot[31065]: time="2025-12-09T15:30:57-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:30:57 volumio go-librespot[31065]: time="2025-12-09T15:30:57-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:30:57 volumio go-librespot[31065]: time="2025-12-09T15:30:57-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:30:57 volumio go-librespot[31065]: time="2025-12-09T15:30:57-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:30:57 volumio go-librespot[31065]: time="2025-12-09T15:30:57-06:00" level=info msg="zeroconf server listening on port 39051" Dec 09 15:30:58 volumio go-librespot[31065]: time="2025-12-09T15:30:58-06:00" level=debug msg="obtained new client token: AABWbOyLPFyhNCPLPzrJH6G0czrwYCJD3uc6erSLarevCI/o5i4sefORKnYYL/GZQ6ABlK04dEq0RDJcOt4e7ud3v08g3f3EF6nDc9BYPTJPErt1hv8XFY5yTYl8xlCCS73ZRWGs19WvP6RnOQ4SDnIdNCC9kqOaqwFZrXiJ1wcJMOG6aizNnXLRkj+in2qi69VaYJ9EG9S2S5+r/897Q2eBEx9S8muTMLi78Dv/MgpMrdeRexjU" Dec 09 15:30:58 volumio go-librespot[31065]: time="2025-12-09T15:30:58-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:30:58 volumio go-librespot[31065]: time="2025-12-09T15:30:58-06:00" level=debug msg="completed keyexchange" Dec 09 15:30:58 volumio go-librespot[31065]: time="2025-12-09T15:30:58-06:00" level=debug msg="completed challenge" Dec 09 15:30:58 volumio go-librespot[31065]: time="2025-12-09T15:30:58-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:30:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:30:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:30:58 volumio volumio[31049]: info: ------------------------------------------- Dec 09 15:30:58 volumio volumio[31049]: info: ----- Volumio3 ---- Dec 09 15:30:58 volumio volumio[31049]: info: ------------------------------------------- Dec 09 15:30:58 volumio volumio[31049]: info: ----- System startup ---- Dec 09 15:30:58 volumio volumio[31049]: info: ------------------------------------------- Dec 09 15:30:59 volumio volumio[31049]: info: MYVOLUMIO Environment detected Dec 09 15:30:59 volumio volumio[31049]: info: Plugin folders cleanup Dec 09 15:30:59 volumio volumio[31049]: info: Scanning into folder /volumio/app/plugins/ Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category audio_interface Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category miscellanea Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category music_service Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category plugins.json Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category system_controller Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category user_interface Dec 09 15:30:59 volumio volumio[31049]: info: Scanning into folder /data/plugins/ Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category audio_interface Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category music_service Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category system_controller Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category system_hardware Dec 09 15:30:59 volumio volumio[31049]: info: Scanning category user_interface Dec 09 15:30:59 volumio volumio[31049]: info: Plugin folders cleanup completed Dec 09 15:30:59 volumio volumio[31049]: info: ------------------------------------------- Dec 09 15:30:59 volumio volumio[31049]: info: ----- Core plugins startup ---- Dec 09 15:30:59 volumio volumio[31049]: info: ------------------------------------------- Dec 09 15:30:59 volumio volumio[31049]: info: Loading plugins from folder /volumio/app/plugins/ Dec 09 15:30:59 volumio volumio[31049]: info: Adding plugin upnp to MyMusic Plugins Dec 09 15:30:59 volumio volumio[31049]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 09 15:30:59 volumio volumio[31049]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 09 15:30:59 volumio volumio[31049]: info: Loading plugins from folder /data/plugins/ Dec 09 15:30:59 volumio volumio[31049]: info: Loading plugin "system"... Dec 09 15:30:59 volumio volumio[31049]: info: Loading plugin "appearance"... Dec 09 15:31:00 volumio volumio[31049]: info: Loading plugin "network"... Dec 09 15:31:00 volumio volumio[31049]: info: Refreshing Cached IP Addresses Dec 09 15:31:00 volumio sudo[31085]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 09 15:31:00 volumio sudo[31085]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:00 volumio sudo[31087]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 09 15:31:00 volumio sudo[31087]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:00 volumio sudo[31087]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:00 volumio sudo[31085]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:00 volumio volumio[31049]: info: Loading plugin "services"... Dec 09 15:31:00 volumio volumio[31049]: info: Loading plugin "alsa_controller"... Dec 09 15:31:00 volumio sudo[31096]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 09 15:31:00 volumio sudo[31096]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:00 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 15:31:00 volumio volumio[31049]: info: Loading plugin "wizard"... Dec 09 15:31:00 volumio volumio[31049]: info: Loading plugin "networkfs"... Dec 09 15:31:00 volumio volumio[31049]: info: Starting Udev Watcher for removable devices Dec 09 15:31:00 volumio volumio[31049]: info: Ignoring mount for partition: boot Dec 09 15:31:00 volumio volumio[31049]: info: Ignoring mount for partition: volumio Dec 09 15:31:00 volumio volumio[31049]: info: Ignoring mount for partition: volumio_data Dec 09 15:31:00 volumio volumio[31049]: info: Mounting Device Wikipedia Dec 09 15:31:01 volumio sudo[31124]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 09 15:31:01 volumio sudo[31124]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:01 volumio sudo[31124]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:01 volumio volumio[31049]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 09 15:31:01 volumio volumio[31049]: dmesg(1) may have more information after failed mount system call. Dec 09 15:31:01 volumio volumio[31049]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 09 15:31:01 volumio volumio[31049]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 09 15:31:01 volumio volumio[31049]: dmesg(1) may have more information after failed mount system call. Dec 09 15:31:01 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 15:31:01 volumio volumio[31049]: info: Loading plugin "volumio_command_line_client"... Dec 09 15:31:01 volumio volumio[31049]: info: Loading plugin "upnp"... Dec 09 15:31:01 volumio volumio[31049]: info: [1765315861054] Starting Upmpd Daemon Dec 09 15:31:01 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 15:31:01 volumio volumio[31049]: info: Loading plugin "my_music"... Dec 09 15:31:01 volumio volumio[31049]: info: Loading plugin "mpd"... Dec 09 15:31:01 volumio volumio-remote-updater[9752]: [2025-12-09 15:31:01] [connect] Successful connection Dec 09 15:31:01 volumio sudo[31096]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:01 volumio volumio[31049]: info: Loading plugin "upnp_browser"... Dec 09 15:31:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 170. Dec 09 15:31:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:01 volumio go-librespot[31126]: go-librespot daemon starting... Dec 09 15:31:01 volumio go-librespot[31127]: time="2025-12-09T15:31:01-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:31:01 volumio go-librespot[31127]: time="2025-12-09T15:31:01-06:00" level=debug msg="app state loaded" Dec 09 15:31:01 volumio go-librespot[31127]: time="2025-12-09T15:31:01-06:00" level=debug msg="stored credentials not found" Dec 09 15:31:01 volumio go-librespot[31127]: time="2025-12-09T15:31:01-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:31:01 volumio go-librespot[31127]: time="2025-12-09T15:31:01-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:31:01 volumio go-librespot[31127]: time="2025-12-09T15:31:01-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:31:01 volumio go-librespot[31127]: time="2025-12-09T15:31:01-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:31:01 volumio go-librespot[31127]: time="2025-12-09T15:31:01-06:00" level=info msg="zeroconf server listening on port 46463" Dec 09 15:31:02 volumio go-librespot[31127]: time="2025-12-09T15:31:02-06:00" level=debug msg="obtained new client token: AADkDTkshQAX9fpFBZoaEsJvmcX7MWGyOAPhPlddOHwyiTEM+rfSTvYFSRkY3V7UvR0JNVfW2aPCY44SotWPmpOewMIHW9Q63WURzf+r7Hz34XvQBftezjxzeiEMH+tE2AgBc7wFKPve778o34fE7qR1WLRAZsKBTbMRUnQ0xSMeNdDgxFzufOsVL+RIj66HlA/QRRvN7U+v7/qkaZD72NN2QQqMGiTVQkMknaUpogCLObpwWpteR6oiBA==" Dec 09 15:31:02 volumio go-librespot[31127]: time="2025-12-09T15:31:02-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:31:02 volumio volumio[31049]: info: Loading plugin "alarm-clock"... Dec 09 15:31:03 volumio volumio[31049]: info: Loading plugin "airplay_emulation"... Dec 09 15:31:03 volumio volumio[31049]: info: Starting Shairport Sync Dec 09 15:31:03 volumio volumio[31049]: info: Loading plugin "last_100"... Dec 09 15:31:03 volumio volumio[31049]: info: Loading plugin "webradio"... Dec 09 15:31:03 volumio volumio[31049]: info: Loading plugin "i2s_dacs"... Dec 09 15:31:03 volumio volumio[31049]: info: I2S DAC not set, start Auto-detection Dec 09 15:31:03 volumio volumio[31049]: info: Loading plugin "volumiodiscovery"... Dec 09 15:31:03 volumio volumio[31049]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 09 15:31:03 volumio volumio[31049]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 15:31:03 volumio volumio[31049]: *** WARNING *** For more information see Dec 09 15:31:03 volumio volumio[31049]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 09 15:31:03 volumio volumio[31049]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 15:31:03 volumio volumio[31049]: *** WARNING *** For more information see Dec 09 15:31:03 volumio node[31049]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 09 15:31:03 volumio node[31049]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 15:31:03 volumio node[31049]: *** WARNING *** For more information see Dec 09 15:31:03 volumio node[31049]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 09 15:31:03 volumio node[31049]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 15:31:03 volumio node[31049]: *** WARNING *** For more information see Dec 09 15:31:03 volumio volumio[31049]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 09 15:31:03 volumio volumio[31049]: info: Discovery: Started advertising with name: Volumio Dec 09 15:31:03 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 15:31:03 volumio volumio[31049]: info: Loading plugin "bandcamp"... Dec 09 15:31:03 volumio go-librespot[31127]: time="2025-12-09T15:31:03-06:00" level=debug msg="completed keyexchange" Dec 09 15:31:03 volumio go-librespot[31127]: time="2025-12-09T15:31:03-06:00" level=debug msg="completed challenge" Dec 09 15:31:03 volumio go-librespot[31127]: time="2025-12-09T15:31:03-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:31:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:31:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:31:04 volumio volumio[31049]: info: Plugin calmradio is not enabled Dec 09 15:31:04 volumio volumio[31049]: info: Loading plugin "soundcloud"... Dec 09 15:31:04 volumio volumio[31049]: info: Loading plugin "spop"... Dec 09 15:31:05 volumio volumio[31049]: info: Loading plugin "squeezelite_mc"... Dec 09 15:31:06 volumio volumio[31049]: info: Loading plugin "youtube2"... Dec 09 15:31:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171. Dec 09 15:31:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:07 volumio go-librespot[31137]: go-librespot daemon starting... Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=debug msg="app state loaded" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=debug msg="stored credentials not found" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=info msg="zeroconf server listening on port 34717" Dec 09 15:31:07 volumio volumio[31049]: info: Loading plugin "ytcr"... Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=debug msg="obtained new client token: AADZmV0Ao7ObVGs1GU085vRXyQonWNoOnxiNZLXhIL1yHyQpMiDTJyU4MpyNM5TxPTMlmWBuh+BwFMqYYxvryMX3Ka+mvOWn6UGLCtpovy6td8lkR3o8BVu9Qbsm9GqirEhroi2EaxQThULK1AgQtgoR8jDLaihLv3ye5fbrYq3cZ2vrgMgqC65/ezmHplvjeWxyRJECyw2GId0ygZSLYYYIFzOkbaVWynrsCFkz+KUCSBUJcNQGgB4WVg==" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=debug msg="completed keyexchange" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=debug msg="completed challenge" Dec 09 15:31:07 volumio go-librespot[31138]: time="2025-12-09T15:31:07-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:31:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:31:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:31:08 volumio volumio[31049]: info: Loading plugin "ytmusic"... Dec 09 15:31:09 volumio volumio[31049]: info: Plugin now_playing is not enabled Dec 09 15:31:09 volumio volumio[31049]: info: Loading plugin "outputs"... Dec 09 15:31:09 volumio volumio[31049]: info: Loading plugin "albumart"... Dec 09 15:31:09 volumio volumio[31049]: info: Plugin example_plugin is not enabled Dec 09 15:31:09 volumio volumio[31049]: info: Loading plugin "inputs"... Dec 09 15:31:09 volumio volumio[31049]: info: Loading plugin "updater_comm"... Dec 09 15:31:09 volumio volumio[31049]: info: Plugin mpdemulation is not enabled Dec 09 15:31:09 volumio volumio[31049]: info: Loading plugin "rest_api"... Dec 09 15:31:09 volumio volumio[31049]: info: Loading plugin "websocket"... Dec 09 15:31:09 volumio volumio[31049]: info: Starting Socket.io Server version 1.7.4 Dec 09 15:31:09 volumio volumio[31049]: info: Plugin fusiondsp is not enabled Dec 09 15:31:09 volumio volumio[31049]: info: Plugin mpdoutput is not enabled Dec 09 15:31:09 volumio volumio[31049]: info: Plugin RoonBridge is not enabled Dec 09 15:31:09 volumio volumio[31049]: info: Loading plugin "podcast"... Dec 09 15:31:09 volumio volumio[31049]: info: ControllerPodcast::constructor Dec 09 15:31:09 volumio volumio[31049]: info: Loading plugin "volusonic"... Dec 09 15:31:09 volumio volumio[31148]: Forking 3 albumart workers Dec 09 15:31:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 172. Dec 09 15:31:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:10 volumio go-librespot[31188]: go-librespot daemon starting... Dec 09 15:31:10 volumio go-librespot[31189]: time="2025-12-09T15:31:10-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:31:10 volumio go-librespot[31189]: time="2025-12-09T15:31:10-06:00" level=debug msg="app state loaded" Dec 09 15:31:10 volumio go-librespot[31189]: time="2025-12-09T15:31:10-06:00" level=debug msg="stored credentials not found" Dec 09 15:31:10 volumio go-librespot[31189]: time="2025-12-09T15:31:10-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:31:11 volumio go-librespot[31189]: time="2025-12-09T15:31:11-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:31:11 volumio go-librespot[31189]: time="2025-12-09T15:31:11-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:31:11 volumio go-librespot[31189]: time="2025-12-09T15:31:11-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:31:11 volumio go-librespot[31189]: time="2025-12-09T15:31:11-06:00" level=info msg="zeroconf server listening on port 43965" Dec 09 15:31:11 volumio go-librespot[31189]: time="2025-12-09T15:31:11-06:00" level=debug msg="obtained new client token: AAASzFasNaJXqAWcLjDlxempWkIZI+J12kW5PWNpBkMyoJ0moZ1Vg2J9bv7TVXu9xk/bCpQrCE4alOrzn/jla9XdzznYkZrnIH8xQSJJGz7himZa+kWBXeZe4opzKwjeP3NEl6fack5offo7XWr2PKEVKtRObF2TD+Ir1JSzcw8vG1BPrnALN8MEmPg9q7JqT6XPqVnrblm5fhq6aOtqeMd28wy9WQNG3iz7pSKj0CXoaeY0ZwP9WBs=" Dec 09 15:31:11 volumio go-librespot[31189]: time="2025-12-09T15:31:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:31:11 volumio go-librespot[31189]: time="2025-12-09T15:31:11-06:00" level=debug msg="completed keyexchange" Dec 09 15:31:11 volumio go-librespot[31189]: time="2025-12-09T15:31:11-06:00" level=debug msg="completed challenge" Dec 09 15:31:11 volumio go-librespot[31189]: time="2025-12-09T15:31:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:31:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:31:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:31:11 volumio volumio[31159]: Starting albumart workers Dec 09 15:31:11 volumio volumio[31049]: info: Applying required configuration parameters for plugin volusonic Dec 09 15:31:11 volumio volumio[31049]: info: Loading plugin "backup_restore"... Dec 09 15:31:11 volumio volumio[31158]: Starting albumart workers Dec 09 15:31:11 volumio volumio[31160]: Starting albumart workers Dec 09 15:31:11 volumio volumio[31049]: info: Applying required configuration parameters for plugin backup_restore Dec 09 15:31:11 volumio volumio[31049]: info: Plugin rpi_eeprom_config is not enabled Dec 09 15:31:11 volumio volumio[31049]: info: Plugin rpi_eeprom_updater is not enabled Dec 09 15:31:11 volumio volumio[31049]: info: Loading plugin "scheduledrestart"... Dec 09 15:31:12 volumio volumio[31049]: info: Applying required configuration parameters for plugin scheduledrestart Dec 09 15:31:12 volumio volumio[31049]: info: Plugin Bluetoothremote is not enabled Dec 09 15:31:12 volumio volumio[31049]: info: Plugin music_services_shield is not enabled Dec 09 15:31:12 volumio volumio[31049]: info: Loading plugin "Systeminfo"... Dec 09 15:31:12 volumio volumio[31049]: info: Plugin peppymeterbasic is not enabled Dec 09 15:31:12 volumio volumio[31049]: info: Loading plugin "peppyspectrum"... Dec 09 15:31:12 volumio volumio[31049]: info: Loading i18n strings for locale en Dec 09 15:31:12 volumio volumio[31049]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 09 15:31:12 volumio volumio[31049]: Updating browse sources language Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::initPlayerControls Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:12 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 15:31:12 volumio volumio[31049]: Express server listening on port 3000 Dec 09 15:31:12 volumio volumio[31049]: [Metrics] WebUI: 14s 760.03ms Dec 09 15:31:13 volumio volumio[31049]: info: CoreStateMachine::resetVolumioState Dec 09 15:31:13 volumio volumio[31049]: info: CoreStateMachine::getcurrentVolume Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioRetrievevolume Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:31:13 volumio sudo[31233]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 09 15:31:13 volumio sudo[31233]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:13 volumio sudo[31233]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:13 volumio sudo[31235]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 09 15:31:13 volumio sudo[31235]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:13 volumio sudo[31235]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:13 volumio volumio[31049]: info: Volumio Network Manager: Network status updated: 1 Dec 09 15:31:13 volumio volumio[31049]: info: VolumeController:: Volume=86 Mute =false Dec 09 15:31:13 volumio volumio[31049]: info: CoreStateMachine::pushState Dec 09 15:31:13 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioPushState Dec 09 15:31:13 volumio volumio[31049]: info: CoreStateMachine::updateTrackBlock Dec 09 15:31:13 volumio volumio[31049]: info: CorePlayQueue::getTrackBlock Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioRetrievevolume Dec 09 15:31:13 volumio volumio[31049]: info: Reloading queue from file Dec 09 15:31:13 volumio volumio[31049]: info: CoreStateMachine::setRepeat null single undefined Dec 09 15:31:13 volumio volumio[31049]: info: CoreStateMachine::pushState Dec 09 15:31:13 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioPushState Dec 09 15:31:13 volumio volumio[31049]: info: CoreStateMachine::setRandom null Dec 09 15:31:13 volumio volumio[31049]: info: CoreStateMachine::pushState Dec 09 15:31:13 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioPushState Dec 09 15:31:13 volumio volumio[31049]: info: Setting Device type: Raspberry PI Dec 09 15:31:13 volumio volumio[31049]: info: VolumeController:: Volume=86 Mute =false Dec 09 15:31:13 volumio volumio[31049]: info: CoreStateMachine::pushState Dec 09 15:31:13 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioPushState Dec 09 15:31:13 volumio volumio[31049]: info: Completed loading Core Plugins Dec 09 15:31:13 volumio volumio[31049]: info: Preparing to generate the ALSA configuration file Dec 09 15:31:13 volumio sudo[31248]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 09 15:31:13 volumio sudo[31248]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:13 volumio volumio[31049]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 09 15:31:13 volumio volumio[31049]: info: Reading ALSA contributions from plugins. Dec 09 15:31:13 volumio volumio[31049]: info: Asound.conf file unchanged, so no further update is needed Dec 09 15:31:13 volumio volumio[31049]: info: Output device has changed, restarting MPD Dec 09 15:31:13 volumio sudo[31248]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:13 volumio volumio[31049]: info: Output device has changed, restarting Shairport Sync Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:31:13 volumio sudo[31251]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 15:31:13 volumio sudo[31251]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:13 volumio sudo[31251]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:13 volumio sudo[31253]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 15:31:13 volumio sudo[31253]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:13 volumio volumio[31049]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 15:31:13 volumio volumio[31049]: info: ___________ START PLUGINS ___________ Dec 09 15:31:13 volumio volumio[31049]: info: ControllerMpd::onStart: Initializing MPD Dec 09 15:31:13 volumio volumio[31049]: info: Creating MPD Configuration file Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:31:13 volumio volumio[31049]: info: [1765315873512] CoreMusicLibrary::Adding element Media Servers Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:13 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 09 15:31:13 volumio sudo[31261]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 15:31:13 volumio sudo[31261]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:13 volumio sudo[31261]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:13 volumio sudo[31263]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:31:13 volumio sudo[31263]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:13 volumio volumio[31049]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:31:13 volumio volumio[31049]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:31:13 volumio volumio[31049]: info: [1765315873625] CoreMusicLibrary::Adding element Last_100 Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:13 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 09 15:31:13 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 15:31:13 volumio systemd[1]: mpd.service: Consumed 4.539s CPU time. Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:31:13 volumio volumio[31049]: info: [1765315873638] CoreMusicLibrary::Adding element Webradio Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:13 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 09 15:31:13 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 15:31:13 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 15:31:13 volumio volumio[31049]: info: Initializing BBC Radios Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:31:13 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:31:13 volumio volumio[31049]: info: [1765315873710] CoreMusicLibrary::Adding element Bandcamp Discover Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:13 volumio volumio[31049]: Cannot find translation for source Bandcamp Discover Dec 09 15:31:13 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:31:13 volumio volumio[31049]: info: [1765315873729] CoreMusicLibrary::Adding element SoundCloud Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:13 volumio volumio[31049]: Cannot find translation for source Bandcamp Discover Dec 09 15:31:13 volumio volumio[31049]: Cannot find translation for source SoundCloud Dec 09 15:31:13 volumio volumio[31049]: info: Creating Spotify config file Dec 09 15:31:13 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:13 volumio volumio-remote-updater[9752]: [2025-12-09 15:31:13] [connect] Successful connection Dec 09 15:31:13 volumio sudo[31288]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 09 15:31:13 volumio sudo[31288]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 09 15:31:13 volumio sudo[31288]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:14 volumio volumio[31049]: info: [squeezelite_mc] Starting proxy server... Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:31:14 volumio volumio[31049]: info: [1765315874089] CoreMusicLibrary::Adding element YouTube2 Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Bandcamp Discover Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source SoundCloud Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube2 Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:31:14 volumio volumio[31049]: info: [1765315874107] CoreMusicLibrary::Adding element YouTube Music Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Bandcamp Discover Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source SoundCloud Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube2 Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube Music Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:31:14 volumio volumio[31049]: info: [1765315874119] CoreMusicLibrary::Adding element Podcast Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Bandcamp Discover Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source SoundCloud Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube2 Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube Music Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Podcast Dec 09 15:31:14 volumio volumio[31049]: info: Loading i18n strings for locale en Dec 09 15:31:14 volumio volumio[31049]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 09 15:31:14 volumio volumio[31049]: Updating browse sources language Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Bandcamp Discover Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source SoundCloud Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube2 Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube Music Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Podcast Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Bandcamp Discover Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source SoundCloud Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube2 Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube Music Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Podcast Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:31:14 volumio volumio[31049]: info: [1765315874176] CoreMusicLibrary::Adding element Volusonic Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Bandcamp Discover Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source SoundCloud Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube2 Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source YouTube Music Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Podcast Dec 09 15:31:14 volumio volumio[31049]: Cannot find translation for source Volusonic Dec 09 15:31:14 volumio volumio[31049]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 09 15:31:14 volumio volumio[31049]: info: Volumio Calling Home Dec 09 15:31:14 volumio volumio[31049]: info: [squeezelite_mc] Proxy server started on port 38353 Dec 09 15:31:14 volumio volumio[31049]: info: Preparing to generate the ALSA configuration file Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::volumioRetrievevolume Dec 09 15:31:14 volumio volumio[31049]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 09 15:31:14 volumio volumio[31049]: info: Discovery: Found device Volumio Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::volumioGetState Dec 09 15:31:14 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:14 volumio volumio[31049]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 09 15:31:14 volumio volumio[31049]: info: Discovery: Found device Volumio Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::volumioGetState Dec 09 15:31:14 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:14 volumio volumio[31049]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 09 15:31:14 volumio volumio[31049]: info: Reading ALSA contributions from plugins. Dec 09 15:31:14 volumio volumio[31049]: info: MPD Permissions set Dec 09 15:31:14 volumio volumio[31049]: info: MPD Permissions set Dec 09 15:31:14 volumio volumio[31049]: info: Upmpdcli Daemon Started Dec 09 15:31:14 volumio volumio-remote-updater[9752]: [2025-12-09 15:31:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765315873 101 Dec 09 15:31:14 volumio volumio[31049]: 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 Dec 09 15:31:14 volumio volumio[31049]: info: Spotify config file written Dec 09 15:31:14 volumio sudo[31297]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 09 15:31:14 volumio sudo[31297]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 173. Dec 09 15:31:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:14 volumio volumio[31049]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 09 15:31:14 volumio volumio[31049]: info: VolumeController:: Volume=86 Mute =false Dec 09 15:31:14 volumio volumio[31049]: info: CoreStateMachine::pushState Dec 09 15:31:14 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::volumioPushState Dec 09 15:31:14 volumio volumio[31049]: info: [squeezelite_mc] Server discovery started Dec 09 15:31:14 volumio volumio[31049]: info: [squeezelite_mc] Player finder started Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 09 15:31:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:14 volumio go-librespot[31299]: go-librespot daemon starting... Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:14 volumio go-librespot[31310]: go-librespot daemon starting... Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:31:14 volumio sudo[31297]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio go-librespot[31314]: time="2025-12-09T15:31:14-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:31:14 volumio go-librespot[31314]: time="2025-12-09T15:31:14-06:00" level=debug msg="app state loaded" Dec 09 15:31:14 volumio go-librespot[31314]: time="2025-12-09T15:31:14-06:00" level=debug msg="stored credentials not found" Dec 09 15:31:14 volumio go-librespot[31314]: time="2025-12-09T15:31:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:14 volumio volumio[31049]: info: No need to fix Spotify hosts Dec 09 15:31:14 volumio volumio[31049]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 09 15:31:14 volumio volumio[31049]: info: Volumio called home Dec 09 15:31:15 volumio volumio[31049]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"} Dec 09 15:31:15 volumio volumio[31049]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 09 15:31:15 volumio volumio[31049]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 09 15:31:15 volumio volumio[31049]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 09 15:31:15 volumio go-librespot[31314]: time="2025-12-09T15:31:15-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:31:15 volumio go-librespot[31314]: time="2025-12-09T15:31:15-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:31:15 volumio go-librespot[31314]: time="2025-12-09T15:31:15-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:31:15 volumio go-librespot[31314]: time="2025-12-09T15:31:15-06:00" level=info msg="zeroconf server listening on port 35543" Dec 09 15:31:15 volumio volumio[31049]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 09 15:31:15 volumio volumio[31049]: SPOTIFY: BQAP_nlfcgt4ZG8k-CVHU3998hHZYnnQ11aKR8-SZe3rYg7nYpAZQ1OUHUBd2OU3jHax8dnlPgqMp_Y2ZZb814mgVsbibNImm-v0DOf8SKVL07mlTrMAwHVLzTBnHHNFwMB6wTAjDSWLMlGLgwELs-jWnNMZjvtofBuiMyOETd1UUTKq8Uto3a0oJhU7Cp_aKof5mJFEdJXy-W4wlbk8XEBvi2xZLcgDvNEI6F4 Dec 09 15:31:15 volumio volumio[31049]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 09 15:31:15 volumio volumio[31049]: info: New Spotify access token = BQAP_nlfcgt4ZG8k-CVHU3998hHZYnnQ11aKR8-SZe3rYg7nYpAZQ1OUHUBd2OU3jHax8dnlPgqMp_Y2ZZb814mgVsbibNImm-v0DOf8SKVL07mlTrMAwHVLzTBnHHNFwMB6wTAjDSWLMlGLgwELs-jWnNMZjvtofBuiMyOETd1UUTKq8Uto3a0oJhU7Cp_aKof5mJFEdJXy-W4wlbk8XEBvi2xZLcgDvNEI6F4 Dec 09 15:31:15 volumio volumio[31049]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 09 15:31:15 volumio volumio[31049]: info: Starting Shairport Sync Dec 09 15:31:15 volumio volumio[31049]: info: Starting Shairport Sync Dec 09 15:31:15 volumio volumio[31049]: info: Starting Shairport Sync Dec 09 15:31:15 volumio go-librespot[31314]: time="2025-12-09T15:31:15-06:00" level=debug msg="obtained new client token: AACGqosVRTxT8MEqXiLO5QWrAyj37YaH+jyCxvEcekvD9s43YIwLhzARkouyRHAZuLTl2mnb2hoP/BSxdqaEN2bGFw+fhgJ6ikZJFI6y+0FQKyE9fAZXN7OxvGcO6vaJIJCNATAD3xrG5me4wBpr0I+hWQ3413IbvyP/DFkoG73rJWtZDpBrksmK0N/31WdVlIbz2JkDlKoU9GgV4QGxLpIRFSeaP7j3NJOAs2/SVJKLmn1YwxxH5+4=" Dec 09 15:31:15 volumio sudo[31329]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 09 15:31:15 volumio sudo[31329]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:15 volumio sudo[31332]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 15:31:15 volumio sudo[31332]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:15 volumio sudo[31329]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:15 volumio sudo[31334]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 15:31:15 volumio sudo[31334]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:15 volumio go-librespot[31314]: time="2025-12-09T15:31:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:31:15 volumio sudo[31336]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 15:31:15 volumio sudo[31336]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:15 volumio volumio[31049]: info: Asound.conf file unchanged, so no further update is needed Dec 09 15:31:15 volumio volumio[31049]: info: Output device has changed, restarting MPD Dec 09 15:31:15 volumio volumio[31049]: info: Output device has changed, restarting Shairport Sync Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:31:15 volumio go-librespot[31314]: time="2025-12-09T15:31:15-06:00" level=debug msg="completed keyexchange" Dec 09 15:31:15 volumio go-librespot[31314]: time="2025-12-09T15:31:15-06:00" level=debug msg="completed challenge" Dec 09 15:31:15 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 09 15:31:15 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 09 15:31:15 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 15:31:15 volumio systemd[1]: shairport-sync.service: Consumed 1.930s CPU time. Dec 09 15:31:15 volumio sudo[31344]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 15:31:15 volumio sudo[31344]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:15 volumio go-librespot[31314]: time="2025-12-09T15:31:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:31:15 volumio sudo[31342]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 15:31:15 volumio sudo[31342]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:15 volumio sudo[31342]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:15 volumio volumio[31049]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 15:31:15 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 15:31:15 volumio sudo[31332]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:31:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:31:15 volumio volumio[31049]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 09 15:31:15 volumio sudo[31334]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:15 volumio sudo[31336]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:15 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 09 15:31:15 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 15:31:15 volumio systemd[1]: mpd.service: Consumed 1.767s CPU time. Dec 09 15:31:15 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 09 15:31:15 volumio sudo[31357]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 09 15:31:15 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 15:31:15 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 15:31:15 volumio sudo[31357]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:15 volumio sudo[31357]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:15 volumio volumio[31049]: info: MPD Permissions set Dec 09 15:31:15 volumio volumio[31049]: info: Shairport-Sync Started Dec 09 15:31:15 volumio volumio[31049]: Error adding Membership: Error: addMembership EINVAL Dec 09 15:31:15 volumio volumio[31049]: info: Shairport-Sync Started Dec 09 15:31:15 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 15:31:15 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 15:31:15 volumio volumio[31049]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 09 15:31:15 volumio volumio[31049]: info: Shairport-Sync Started Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::volumioGetState Dec 09 15:31:15 volumio sudo[31378]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 09 15:31:15 volumio sudo[31378]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:15 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:15 volumio sudo[31378]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:15 volumio volumio[31049]: info: Starting Shairport Sync Dec 09 15:31:15 volumio volumio[31049]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Dec 09 15:31:15 volumio volumio[31049]: info: Spotify Successfully logged in Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 15:31:15 volumio volumio[31049]: info: [1765315875951] CoreMusicLibrary::Adding element Spotify Dec 09 15:31:15 volumio sudo[31386]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 15:31:15 volumio sudo[31386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:15 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 15:31:15 volumio volumio[31049]: Cannot find translation for source Bandcamp Discover Dec 09 15:31:15 volumio volumio[31049]: Cannot find translation for source SoundCloud Dec 09 15:31:15 volumio volumio[31049]: Cannot find translation for source YouTube2 Dec 09 15:31:15 volumio volumio[31049]: Cannot find translation for source YouTube Music Dec 09 15:31:15 volumio volumio[31049]: Cannot find translation for source Podcast Dec 09 15:31:15 volumio volumio[31049]: Cannot find translation for source Volusonic Dec 09 15:31:15 volumio volumio[31049]: Cannot find translation for source Spotify Dec 09 15:31:15 volumio sudo[31375]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 09 15:31:15 volumio sudo[31375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 09 15:31:15 volumio sudo[31375]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:16 volumio volumio[31049]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 09 15:31:16 volumio sudo[31391]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 09 15:31:16 volumio sudo[31391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:16 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 09 15:31:16 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 09 15:31:16 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 15:31:16 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 15:31:16 volumio sudo[31386]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:16 volumio systemd[1]: Reloading. Dec 09 15:31:16 volumio volumio[31049]: info: Shairport-Sync Started Dec 09 15:31:16 volumio volumio[31049]: info: [squeezelite_mc] Notification listener started Dec 09 15:31:16 volumio volumio[31049]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 09 15:31:16 volumio volumio[31049]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 09 15:31:16 volumio volumio[31049]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 09 15:31:16 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:16 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:16 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 15:31:16 volumio volumio[31049]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 15:31:17 volumio volumio[31049]: info: CoreCommandRouter::volumioGetState Dec 09 15:31:17 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:18 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 09 15:31:18 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 09 15:31:18 volumio volumio[31049]: info: go-librespot daemon successfully initialized Dec 09 15:31:18 volumio sudo[31391]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:18 volumio volumio[31049]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:31:18 volumio sudo[31426]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:31:18 volumio sudo[31426]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:18 volumio sudo[31426]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:18 volumio volumio[31049]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 09 15:31:18 volumio sudo[31429]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 09 15:31:18 volumio sudo[31429]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:18 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 09 15:31:18 volumio volumio[31049]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect' Dec 09 15:31:18 volumio volumio[31049]: info: CoreCommandRouter::volumioGetState Dec 09 15:31:18 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:18 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 09 15:31:18 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 09 15:31:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 09 15:31:18 volumio sudo[31429]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:18 volumio go-librespot[31431]: go-librespot daemon starting... Dec 09 15:31:18 volumio go-librespot[31432]: time="2025-12-09T15:31:18-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:31:18 volumio go-librespot[31432]: time="2025-12-09T15:31:18-06:00" level=debug msg="app state loaded" Dec 09 15:31:18 volumio go-librespot[31432]: time="2025-12-09T15:31:18-06:00" level=debug msg="stored credentials not found" Dec 09 15:31:18 volumio go-librespot[31432]: time="2025-12-09T15:31:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:31:19 volumio go-librespot[31432]: time="2025-12-09T15:31:19-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:31:19 volumio go-librespot[31432]: time="2025-12-09T15:31:19-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:31:19 volumio go-librespot[31432]: time="2025-12-09T15:31:19-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:31:19 volumio go-librespot[31432]: time="2025-12-09T15:31:19-06:00" level=info msg="zeroconf server listening on port 43333" Dec 09 15:31:19 volumio volumio[31049]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:31:19 volumio sudo[31440]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:31:19 volumio sudo[31440]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:19 volumio go-librespot[31432]: time="2025-12-09T15:31:19-06:00" level=debug msg="obtained new client token: AAAwUySA0j/85LBF4jZPfytzTzFO3u8MRQN3w6AfBIh228JxgiZ3CHnOh36FSoE2DHugZzNdnd5nhkLQT0bWBaZM9vuWsYnUhThKr2Txz1ZpjZiXpctmIamYMXSeqrXc8KxjSihSjG2BoYHDplIV6eSeyyVR5aKFEDY5n12LcLjIHp7+e8GVknRz6478K+GcGnB6oVfAxNsFy8l32+B5OXU/BA5sJNqQSChtfljyG138SxSSpY3krjc=" Dec 09 15:31:19 volumio sudo[31440]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:19 volumio volumio[31049]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 09 15:31:19 volumio go-librespot[31432]: time="2025-12-09T15:31:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:31:19 volumio sudo[31444]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 09 15:31:19 volumio sudo[31444]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:19 volumio sudo[31444]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:19 volumio volumio[31049]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 09 15:31:19 volumio go-librespot[31432]: time="2025-12-09T15:31:19-06:00" level=debug msg="completed keyexchange" Dec 09 15:31:19 volumio go-librespot[31432]: time="2025-12-09T15:31:19-06:00" level=debug msg="completed challenge" Dec 09 15:31:19 volumio sudo[31447]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 09 15:31:19 volumio sudo[31447]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:19 volumio go-librespot[31432]: time="2025-12-09T15:31:19-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:31:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:31:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:31:19 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 09 15:31:19 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 09 15:31:19 volumio sudo[31447]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:19 volumio volumio[31049]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect' Dec 09 15:31:19 volumio volumio[31049]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 09 15:31:19 volumio volumio[31049]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 09 15:31:19 volumio volumio[31049]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 09 15:31:19 volumio mpd[31389]: 2025-12-09T15:31:19 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 09 15:31:19 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 09 15:31:19 volumio sudo[31253]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:19 volumio sudo[31344]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:19 volumio sudo[31263]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:20 volumio volumio[31049]: error: MPD error: The expression evaluated to a falsy value: Dec 09 15:31:20 volumio volumio[31049]: assert.ok(self.idling) Dec 09 15:31:20 volumio volumio[31049]: error: The expression evaluated to a falsy value: Dec 09 15:31:20 volumio volumio[31049]: assert.ok(self.idling) Dec 09 15:31:20 volumio volumio[31049]: error: MPD error: The expression evaluated to a falsy value: Dec 09 15:31:20 volumio volumio[31049]: assert.ok(self.idling) Dec 09 15:31:20 volumio volumio[31049]: error: The expression evaluated to a falsy value: Dec 09 15:31:20 volumio volumio[31049]: assert.ok(self.idling) Dec 09 15:31:20 volumio volumio[31049]: error: updateQueue error: null Dec 09 15:31:20 volumio volumio[31049]: info: MPD running with PID31389 Dec 09 15:31:20 volumio volumio[31049]: ,establishing connection Dec 09 15:31:20 volumio volumio[31049]: error: updateQueue error: null Dec 09 15:31:20 volumio volumio[31049]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:31:20 volumio sudo[31458]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:31:20 volumio sudo[31458]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:20 volumio sudo[31458]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:20 volumio volumio[31049]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:31:20 volumio sudo[31461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:31:20 volumio sudo[31461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:20 volumio sudo[31461]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:20 volumio volumio[31049]: info: CoreCommandRouter::volumioGetState Dec 09 15:31:20 volumio volumio[31049]: info: CorePlayQueue::getTrack 0 Dec 09 15:31:21 volumio volumio[31049]: info: Initializing connection to go-librespot Websocket Dec 09 15:31:21 volumio volumio[31049]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 15:31:21 volumio volumio[31049]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:31:21 volumio sudo[31478]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:31:21 volumio sudo[31478]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:21 volumio sudo[31478]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:21 volumio volumio[31049]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:31:21 volumio sudo[31481]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:31:21 volumio sudo[31481]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:21 volumio sudo[31481]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:22 volumio volumio[31049]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 09 15:31:22 volumio sudo[31484]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 09 15:31:22 volumio sudo[31484]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 09 15:31:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:22 volumio go-librespot[31486]: go-librespot daemon starting... Dec 09 15:31:22 volumio sudo[31484]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:22 volumio go-librespot[31487]: time="2025-12-09T15:31:22-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:31:22 volumio go-librespot[31487]: time="2025-12-09T15:31:22-06:00" level=debug msg="app state loaded" Dec 09 15:31:22 volumio go-librespot[31487]: time="2025-12-09T15:31:22-06:00" level=debug msg="stored credentials not found" Dec 09 15:31:22 volumio go-librespot[31487]: time="2025-12-09T15:31:22-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:31:22 volumio volumio[31049]: info: Completed starting Core Plugins Dec 09 15:31:22 volumio volumio[31049]: info: ------------------------------------------- Dec 09 15:31:22 volumio volumio[31049]: info: ----- MyVolumio plugins startup ---- Dec 09 15:31:22 volumio volumio[31049]: info: ------------------------------------------- Dec 09 15:31:22 volumio volumio[31049]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 09 15:31:22 volumio go-librespot[31487]: time="2025-12-09T15:31:22-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 09 15:31:22 volumio go-librespot[31487]: time="2025-12-09T15:31:22-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 09 15:31:22 volumio go-librespot[31487]: time="2025-12-09T15:31:22-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 09 15:31:22 volumio go-librespot[31487]: time="2025-12-09T15:31:22-06:00" level=info msg="zeroconf server listening on port 38125" Dec 09 15:31:22 volumio sudo[31495]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 15:31:22 volumio sudo[31495]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:22 volumio sudo[31497]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 15:31:22 volumio sudo[31497]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:23 volumio go-librespot[31487]: time="2025-12-09T15:31:23-06:00" level=debug msg="obtained new client token: AAD/QcuPPWGQcQyWswZyugoIkM3gn+sutdNWlajb7pN9kZ6dkspnkOMpLx9vMtUrHPKU8MuBUMxhiyiY+W/u473npEnQL6tWssYlalLVPtFVaFL4Z2C4igcO2BzVC3/BTjraxXpMO+rSNxZqK1sEr7Kp4rYqlO1z9p1nOHf5W2vqsLPUQFT8KNWho+E2MFiSqLFv0kHy7mY1GgWPPK08jfdOt6m1n7c4gT/xQuwow8AaKXFIpfhZ+z+Fcw==" Dec 09 15:31:23 volumio sudo[31499]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 15:31:23 volumio sudo[31499]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 15:31:23 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 09 15:31:23 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 09 15:31:23 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 09 15:31:23 volumio go-librespot[31487]: time="2025-12-09T15:31:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:31:23 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 09 15:31:23 volumio sudo[31497]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:23 volumio sudo[31499]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:23 volumio sudo[31495]: pam_unix(sudo:session): session closed for user root Dec 09 15:31:23 volumio mpd_monitor.sh[31503]: MPD Monitor Service: Starting MPD Monitor Service Dec 09 15:31:23 volumio volumio[31049]: info: Successfully started MPD Monitor Dec 09 15:31:23 volumio volumio[31049]: info: Successfully started MPD Monitor Dec 09 15:31:23 volumio volumio[31049]: info: Successfully started MPD Monitor Dec 09 15:31:23 volumio go-librespot[31487]: time="2025-12-09T15:31:23-06:00" level=debug msg="completed keyexchange" Dec 09 15:31:23 volumio go-librespot[31487]: time="2025-12-09T15:31:23-06:00" level=debug msg="completed challenge" Dec 09 15:31:23 volumio go-librespot[31487]: time="2025-12-09T15:31:23-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:31:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:31:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:31:24 volumio volumio[31049]: info: Initializing connection to go-librespot Websocket Dec 09 15:31:24 volumio volumio[31049]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 15:31:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 09 15:31:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:27 volumio go-librespot[31508]: go-librespot daemon starting... Dec 09 15:31:27 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=debug msg="app state loaded" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=debug msg="stored credentials not found" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=info msg="zeroconf server listening on port 36885" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=debug msg="obtained new client token: AACeXIBNw24yWBLen1kLdCz1FmM+pBI9V+glJY8npgXIWPU6xzYO//mznHKc4WC8hNLF8GyK42YY91pDdUSWsGlt4NV7jKTxHMyDvy5pokgMXaEQ0ji+LlXC+0sDzuvDabsydtVyzVeyqqNqjWE7M0lqtiBKEtB40V+xVb+r+ERIv/Ya90tPD7sV++oGlG6a9oD5RuAFyh5Z9z5XFft8qbNsPllyRiCo5vPNcuCZVM24BLuGcXd+RiUWTQ==" Dec 09 15:31:27 volumio volumio[31049]: info: Initializing connection to go-librespot Websocket Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=debug msg="new websocket client" Dec 09 15:31:27 volumio volumio[31049]: info: Connection to go-librespot Websocket established Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=debug msg="completed keyexchange" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=debug msg="completed challenge" Dec 09 15:31:27 volumio go-librespot[31509]: time="2025-12-09T15:31:27-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:31:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:31:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:31:27 volumio volumio[31049]: info: Connection to go-librespot Websocket closed Dec 09 15:31:28 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 09 15:31:28 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 09 15:31:30 volumio volumio[31049]: info: Getting Spotify volume Dec 09 15:31:30 volumio volumio[31049]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 15:31:30 volumio volumio[31049]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 15:31:30 volumio volumio[31049]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 09 15:31:30 volumio volumio[31049]: errno: -111, Dec 09 15:31:30 volumio volumio[31049]: code: 'ECONNREFUSED', Dec 09 15:31:30 volumio volumio[31049]: syscall: 'connect', Dec 09 15:31:30 volumio volumio[31049]: address: '127.0.0.1', Dec 09 15:31:30 volumio volumio[31049]: port: 9879, Dec 09 15:31:30 volumio volumio[31049]: response: undefined Dec 09 15:31:30 volumio volumio[31049]: } Dec 09 15:31:30 volumio volumio[31049]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 15:31:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 09 15:31:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 15:31:31 volumio go-librespot[31553]: go-librespot daemon starting... Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=info msg="running go-librespot 0.4.0" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=debug msg="app state loaded" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=debug msg="stored credentials not found" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=info msg="zeroconf server listening on port 39691" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=debug msg="obtained new client token: AAAJHhq9Q6Dw9pOXhyrCcfWMwzN8ynHNqy/4bAII6ieo88CyAZjyVIhYs4fYKeaLLG2Wr5yh84POtEYfQ+PZvrQwMUJ0ISrqr/Ub64A03PBqirhQlIkBJ06fxoBIUhRdPJaGO3Zy2HTjOm2KERCiqoPau/NPKbQ/S1V3NKEPWb+9zVSnTJ4ut/zHc5NBGzV/Dn3ygDqutvYT59KCutaiBOEpMLYxmVC7Prpu/ZDJpkBUB+iZcxY2Ieug0Q==" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=debug msg="completed keyexchange" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=debug msg="completed challenge" Dec 09 15:31:31 volumio go-librespot[31563]: time="2025-12-09T15:31:31-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 15:31:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 15:31:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 15:31:31 volumio sudo[31579]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 15:30' Dec 09 15:31:31 volumio sudo[31579]: 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="ac7dd5922ede329d1459d48b226ddc71f5209a2c" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="3441cddd43405c36fe444484553f10f2f5bc830b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Nov 13 11:04:27 UTC 2025" VOLUMIO_VERSION="4.069" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="7da8d6d9f8baf8621af4ec2af5a00f00"