-- Logs begin at Thu 2025-10-30 14:25:06 CDT, end at Thu 2025-10-30 16:13:39 CDT. -- Oct 30 16:12:01 music volumio[962]: info: Getting Spotify volume Oct 30 16:12:01 music volumio[962]: (node:962) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:01 music volumio[962]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Oct 30 16:12:01 music volumio[962]: (node:962) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 706) Oct 30 16:12:01 music volumio[962]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 30 16:12:01 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:12:01 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:01 music volumio[962]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Oct 30 16:12:02 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:02 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:02 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:02 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8455. Oct 30 16:12:02 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:02 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:02 music go-librespot[15156]: go-librespot daemon starting... Oct 30 16:12:02 music go-librespot[15156]: time="2025-10-30T16:12:02-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:02 music go-librespot[15156]: time="2025-10-30T16:12:02-05:00" level=debug msg="app state loaded" Oct 30 16:12:02 music go-librespot[15156]: time="2025-10-30T16:12:02-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:02 music go-librespot[15156]: time="2025-10-30T16:12:02-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:02 music go-librespot[15156]: time="2025-10-30T16:12:02-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Oct 30 16:12:02 music go-librespot[15156]: time="2025-10-30T16:12:02-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 30 16:12:02 music go-librespot[15156]: time="2025-10-30T16:12:02-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 30 16:12:02 music go-librespot[15156]: time="2025-10-30T16:12:02-05:00" level=info msg="zeroconf server listening on port 37181" Oct 30 16:12:02 music go-librespot[15156]: time="2025-10-30T16:12:02-05:00" level=debug msg="obtained new client token: AAA5NF2otLl0kB8mOtUmHMqOD+CTSB1r61qvUuO0Gu6smFGoTiNq3puQeS/eEKHyXGb4WYHzxJqRYEdpgtmdXSBFo3YMlz70pomZFkeuFL0LKL7CzAHhtngtN2QKPupkwi4WvK+sK75GUJycKNVmK1JREA1tlANOOYDAmaLDn5wbDg5MI4l73tZFbFhPVf3BNXT7HO86zJ7HTGpACafMac2arnir2sl0ES2iUb/hAdEybm8pppZFcXrA0A==" Oct 30 16:12:03 music go-librespot[15156]: time="2025-10-30T16:12:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:03 music go-librespot[15156]: time="2025-10-30T16:12:03-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:03 music go-librespot[15156]: time="2025-10-30T16:12:03-05:00" level=debug msg="completed challenge" Oct 30 16:12:03 music go-librespot[15156]: time="2025-10-30T16:12:03-05: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 " Oct 30 16:12:03 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:03 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:05 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:05 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:05 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:12:05 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:06 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:06 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8456. Oct 30 16:12:06 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:06 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:06 music go-librespot[15206]: go-librespot daemon starting... Oct 30 16:12:06 music go-librespot[15206]: time="2025-10-30T16:12:06-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:06 music go-librespot[15206]: time="2025-10-30T16:12:06-05:00" level=debug msg="app state loaded" Oct 30 16:12:06 music go-librespot[15206]: time="2025-10-30T16:12:06-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:06 music go-librespot[15206]: time="2025-10-30T16:12:06-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:06 music go-librespot[15206]: time="2025-10-30T16:12:06-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Oct 30 16:12:06 music go-librespot[15206]: time="2025-10-30T16:12:06-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 30 16:12:06 music go-librespot[15206]: time="2025-10-30T16:12:06-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 30 16:12:06 music go-librespot[15206]: time="2025-10-30T16:12:06-05:00" level=info msg="zeroconf server listening on port 32919" Oct 30 16:12:06 music go-librespot[15206]: time="2025-10-30T16:12:06-05:00" level=debug msg="obtained new client token: AABoK9HC7Uhik8an99EVABRUjBKfOqy1qG90Qhir7sIs/DQbyItpYty0qRaiB1b4LVk9CmSPJLhOAA+WpDslaWGacTxIW0ULm32jIRDUCkU+7mce7inCz/OdycP3gHsunFjPAA2SuKY8s1EXAM7ZsepyEflV07GntQjibPKjOqKKcsnEepKYU/v1qekkTCV2apwOZlPP5SliG3zsnuzVrlOzs9omHxm5fJczzZDoNxDOnM776g8zt7Om3Q==" Oct 30 16:12:06 music go-librespot[15206]: time="2025-10-30T16:12:06-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:07 music go-librespot[15206]: time="2025-10-30T16:12:07-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:07 music go-librespot[15206]: time="2025-10-30T16:12:07-05:00" level=debug msg="completed challenge" Oct 30 16:12:07 music go-librespot[15206]: time="2025-10-30T16:12:07-05: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 " Oct 30 16:12:07 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:07 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:08 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:08 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:10 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:10 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8457. Oct 30 16:12:10 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:10 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:10 music go-librespot[15230]: go-librespot daemon starting... Oct 30 16:12:10 music go-librespot[15230]: time="2025-10-30T16:12:10-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:10 music go-librespot[15230]: time="2025-10-30T16:12:10-05:00" level=debug msg="app state loaded" Oct 30 16:12:10 music go-librespot[15230]: time="2025-10-30T16:12:10-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:10 music go-librespot[15230]: time="2025-10-30T16:12:10-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:10 music go-librespot[15230]: time="2025-10-30T16:12:10-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:10 music go-librespot[15230]: time="2025-10-30T16:12:10-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:10 music go-librespot[15230]: time="2025-10-30T16:12:10-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:10 music go-librespot[15230]: time="2025-10-30T16:12:10-05:00" level=info msg="zeroconf server listening on port 40329" Oct 30 16:12:10 music go-librespot[15230]: time="2025-10-30T16:12:10-05:00" level=debug msg="obtained new client token: AAAILWdzW7VDWDLUOGYLLwG9+09hNF3BscmjNLHOCWKhvUdQKcV2wVwCRsJLly4HnACmE0+Al1HBdVD8fiN9tOmryiObKo0bpoyPgIUSj1LECTiLSGb4TbBx0HYLRtucUKvT0ixzwY5NhSNsJsBDrOgDd6J7+O0TTWDOc45bySdYASbeJmavxhKy8zCJug3DTG1j2Rodr1pZnL/hqF7nKy/qWW9Kx2RWC916wXr82OQlmZiytOPbSCUQrA==" Oct 30 16:12:11 music go-librespot[15230]: time="2025-10-30T16:12:11-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:11 music go-librespot[15230]: time="2025-10-30T16:12:11-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:11 music go-librespot[15230]: time="2025-10-30T16:12:11-05:00" level=debug msg="completed challenge" Oct 30 16:12:11 music go-librespot[15230]: time="2025-10-30T16:12:11-05: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 " Oct 30 16:12:11 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:11 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:11 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:11 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:11 music volumio[962]: info: Oct 30 16:12:11 music volumio[962]: ---------------------------- Client requests Volumio stop Oct 30 16:12:11 music volumio[962]: info: CoreCommandRouter::volumioStop Oct 30 16:12:11 music volumio[962]: info: CoreStateMachine::stop Oct 30 16:12:11 music volumio[962]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 16:12:11 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:12:11 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:11 music volumio[962]: info: Listing playlists Oct 30 16:12:11 music volumio[962]: info: Listing playlists Oct 30 16:12:14 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:14 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:14 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:14 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8458. Oct 30 16:12:14 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:14 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:14 music go-librespot[15238]: go-librespot daemon starting... Oct 30 16:12:14 music go-librespot[15238]: time="2025-10-30T16:12:14-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:14 music go-librespot[15238]: time="2025-10-30T16:12:14-05:00" level=debug msg="app state loaded" Oct 30 16:12:14 music go-librespot[15238]: time="2025-10-30T16:12:14-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:14 music go-librespot[15238]: time="2025-10-30T16:12:14-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:14 music go-librespot[15238]: time="2025-10-30T16:12:14-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:14 music go-librespot[15238]: time="2025-10-30T16:12:14-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:14 music go-librespot[15238]: time="2025-10-30T16:12:14-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:14 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:12:14 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:14 music go-librespot[15238]: time="2025-10-30T16:12:14-05:00" level=info msg="zeroconf server listening on port 34999" Oct 30 16:12:14 music go-librespot[15238]: time="2025-10-30T16:12:14-05:00" level=debug msg="obtained new client token: AAB4oHeJIlMXJs0qAHruUUy32YBKp7gjkH3J9MJFp3+s3PbJ4ew3UBlfFZyFqZxDrb55/aALd1y9fCTF/Twz8lHEUefuaPUkkNlCqnSvNIOFBxbvKI/BSwSYnufPq6L7IEZZp0gAZrdMb4IZAuuHiF/bVFxJ1pC6PxL4h0sysRqp60ofAi+Lvhy7EJbdBN4GXg7ySNV0O9lD/s9Md3rJxKT05G47dP3PJ27ng7HkXWmhXjctihyuWo5R3Q==" Oct 30 16:12:15 music go-librespot[15238]: time="2025-10-30T16:12:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:15 music go-librespot[15238]: time="2025-10-30T16:12:15-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:15 music go-librespot[15238]: time="2025-10-30T16:12:15-05:00" level=debug msg="completed challenge" Oct 30 16:12:15 music go-librespot[15238]: time="2025-10-30T16:12:15-05: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 " Oct 30 16:12:15 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:15 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:17 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:17 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:18 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:18 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8459. Oct 30 16:12:18 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:18 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:18 music go-librespot[15246]: go-librespot daemon starting... Oct 30 16:12:18 music go-librespot[15246]: time="2025-10-30T16:12:18-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:18 music go-librespot[15246]: time="2025-10-30T16:12:18-05:00" level=debug msg="app state loaded" Oct 30 16:12:18 music go-librespot[15246]: time="2025-10-30T16:12:18-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:18 music go-librespot[15246]: time="2025-10-30T16:12:18-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:18 music go-librespot[15246]: time="2025-10-30T16:12:18-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:18 music go-librespot[15246]: time="2025-10-30T16:12:18-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:18 music go-librespot[15246]: time="2025-10-30T16:12:18-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:18 music go-librespot[15246]: time="2025-10-30T16:12:18-05:00" level=info msg="zeroconf server listening on port 44589" Oct 30 16:12:18 music go-librespot[15246]: time="2025-10-30T16:12:18-05:00" level=debug msg="obtained new client token: AAAno0gwIqgOtaLN7VDOBB9Ckw/zkPsvbh5F++aqYj8Ui9U7fnH8qUZS+YeB6MbYEW+aT3QUpLakgczvfN6cCxhxvo+AyW8L5KkBUaDZ8VTjFcKLDzDOJWPeWL05AlFi5s+JSwRJLE5H3ez7Ymcj3ymrJCqByVr0r4QrX51HGHx39SyEOwpLG75za8a9NrxHHslgc8g/5XXu8UhPAmJh4uBggE+mWh4/tW9KPOphbbraj895XActfApkyQ==" Oct 30 16:12:19 music go-librespot[15246]: time="2025-10-30T16:12:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:19 music go-librespot[15246]: time="2025-10-30T16:12:19-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:19 music go-librespot[15246]: time="2025-10-30T16:12:19-05:00" level=debug msg="completed challenge" Oct 30 16:12:19 music go-librespot[15246]: time="2025-10-30T16:12:19-05: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 " Oct 30 16:12:19 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:19 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:20 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:20 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:22 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:22 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8460. Oct 30 16:12:22 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:22 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:22 music go-librespot[15268]: go-librespot daemon starting... Oct 30 16:12:22 music go-librespot[15268]: time="2025-10-30T16:12:22-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:22 music go-librespot[15268]: time="2025-10-30T16:12:22-05:00" level=debug msg="app state loaded" Oct 30 16:12:22 music go-librespot[15268]: time="2025-10-30T16:12:22-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:22 music go-librespot[15268]: time="2025-10-30T16:12:22-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:22 music go-librespot[15268]: time="2025-10-30T16:12:22-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Oct 30 16:12:22 music go-librespot[15268]: time="2025-10-30T16:12:22-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 30 16:12:22 music go-librespot[15268]: time="2025-10-30T16:12:22-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 30 16:12:22 music go-librespot[15268]: time="2025-10-30T16:12:22-05:00" level=info msg="zeroconf server listening on port 37269" Oct 30 16:12:22 music go-librespot[15268]: time="2025-10-30T16:12:22-05:00" level=debug msg="obtained new client token: AADKXlZgTcpY/hjpZlrRSaIWhQiKYg9L5MP+JQddZ1rBQNoIYgfiGIESCpkZNTzTOJ6fxtVmZwgvKrEPQUrzq0LZ/6DcExhqjIpGNEZLfAoF0ob6xNfDwo7/F5Y2TVdfff+3VNu5391oMy8FL8o1NsiHolbKvyEbHZabaczSGyFBkkUgQEBbkKKJtWIC6wBQDrMKqUEoPIh706gqifoQDor9/qdBhLb0MzEwGa1SMlsxh49g37eEj5CauA==" Oct 30 16:12:23 music go-librespot[15268]: time="2025-10-30T16:12:23-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:23 music go-librespot[15268]: time="2025-10-30T16:12:23-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:23 music go-librespot[15268]: time="2025-10-30T16:12:23-05:00" level=debug msg="completed challenge" Oct 30 16:12:23 music go-librespot[15268]: time="2025-10-30T16:12:23-05: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 " Oct 30 16:12:23 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:23 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:23 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:23 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:23 music volumio[962]: info: Oct 30 16:12:23 music volumio[962]: ---------------------------- Client requests Volumio play Oct 30 16:12:23 music volumio[962]: info: CoreCommandRouter::volumioPlay Oct 30 16:12:23 music volumio[962]: info: CoreStateMachine::play index undefined Oct 30 16:12:23 music volumio[962]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 16:12:23 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:23 music volumio[962]: info: CoreStateMachine::startPlaybackTimer Oct 30 16:12:23 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:23 music volumio[962]: info: [1761858743305] ControllerWebradio::clearAddPlayTrack Oct 30 16:12:23 music volumio[962]: verbose: ControllerMpd::sendMpdCommand stop Oct 30 16:12:23 music volumio[962]: info: sendMpdCommand stop took 7 milliseconds Oct 30 16:12:23 music volumio[962]: verbose: ControllerMpd::sendMpdCommand clear Oct 30 16:12:23 music volumio[962]: info: sendMpdCommand clear took 1 milliseconds Oct 30 16:12:23 music volumio[962]: verbose: ControllerMpd::sendMpdCommand load "https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY" Oct 30 16:12:23 music volumio[962]: info: Oct 30 16:12:23 music volumio[962]: ---------------------------- MPD announces system playlist update Oct 30 16:12:23 music volumio[962]: info: Ignoring MPD Status Update Oct 30 16:12:23 music volumio[962]: info: Oct 30 16:12:23 music volumio[962]: ---------------------------- MPD announces system playlist update Oct 30 16:12:23 music volumio[962]: info: Ignoring MPD Status Update Oct 30 16:12:23 music volumio[962]: info: Oct 30 16:12:23 music volumio[962]: ---------------------------- MPD announces system playlist update Oct 30 16:12:23 music volumio[962]: info: Ignoring MPD Status Update Oct 30 16:12:23 music volumio[962]: error: Upnp client error: Error: This socket has been ended by the other party Oct 30 16:12:23 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:12:23 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:23 music volumio[962]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 30 16:12:23 music volumio[962]: info: CoreStateMachine::ClearQueue Oct 30 16:12:23 music volumio[962]: info: CoreStateMachine::stop Oct 30 16:12:23 music volumio[962]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 16:12:23 music volumio[962]: info: CorePlayQueue::clearPlayQueue Oct 30 16:12:23 music volumio[962]: info: CorePlayQueue::saveQueue Oct 30 16:12:23 music volumio[962]: info: CoreCommandRouter::volumioPushQueue Oct 30 16:12:23 music volumio[962]: info: CoreStateMachine::addQueueItems Oct 30 16:12:23 music volumio[962]: info: CorePlayQueue::addQueueItems Oct 30 16:12:23 music volumio[962]: info: Preload queue cleared Oct 30 16:12:23 music volumio[962]: info: Adding Item to queue: http://opml.radiotime.com/Tune.ashx?id=s21192 Oct 30 16:12:23 music volumio[962]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Oct 30 16:12:24 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:12:24 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:26 music volumio[962]: verbose: ControllerMpd::sendMpdCommand add "https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY" Oct 30 16:12:26 music volumio[962]: error: updateQueue error: null Oct 30 16:12:26 music volumio[962]: info: ------------------------------ 2827ms Oct 30 16:12:26 music volumio[962]: info: ------------------------------ 2822ms Oct 30 16:12:26 music volumio[962]: info: ------------------------------ 2820ms Oct 30 16:12:26 music volumio[962]: info: Oct 30 16:12:26 music volumio[962]: ---------------------------- MPD announces system playlist update Oct 30 16:12:26 music volumio[962]: info: Ignoring MPD Status Update Oct 30 16:12:26 music volumio[962]: info: sendMpdCommand add "https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY" took 7 milliseconds Oct 30 16:12:26 music volumio[962]: info: CoreStateMachine::setConsumeUpdateService mpd Oct 30 16:12:26 music volumio[962]: verbose: ControllerMpd::sendMpdCommand play Oct 30 16:12:26 music volumio[962]: info: Oct 30 16:12:26 music volumio[962]: ---------------------------- MPD announces system playlist update Oct 30 16:12:26 music volumio[962]: info: Ignoring MPD Status Update Oct 30 16:12:26 music volumio[962]: info: Oct 30 16:12:26 music volumio[962]: ---------------------------- MPD announces system playlist update Oct 30 16:12:26 music volumio[962]: info: Ignoring MPD Status Update Oct 30 16:12:26 music volumio[962]: info: ------------------------------ 10ms Oct 30 16:12:26 music volumio[962]: info: sendMpdCommand play took 8 milliseconds Oct 30 16:12:26 music volumio[962]: info: ------------------------------ 8ms Oct 30 16:12:26 music volumio[962]: info: ------------------------------ 6ms Oct 30 16:12:26 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:26 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:26 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:26 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8461. Oct 30 16:12:26 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:26 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:26 music go-librespot[15289]: go-librespot daemon starting... Oct 30 16:12:26 music go-librespot[15289]: time="2025-10-30T16:12:26-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:26 music go-librespot[15289]: time="2025-10-30T16:12:26-05:00" level=debug msg="app state loaded" Oct 30 16:12:26 music go-librespot[15289]: time="2025-10-30T16:12:26-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:26 music go-librespot[15289]: time="2025-10-30T16:12:26-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:26 music go-librespot[15289]: time="2025-10-30T16:12:26-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:26 music go-librespot[15289]: time="2025-10-30T16:12:26-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:26 music go-librespot[15289]: time="2025-10-30T16:12:26-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:26 music go-librespot[15289]: time="2025-10-30T16:12:26-05:00" level=info msg="zeroconf server listening on port 32851" Oct 30 16:12:27 music go-librespot[15289]: time="2025-10-30T16:12:27-05:00" level=debug msg="obtained new client token: AACv+l3NDy99+ysIH1DknjmtuJ3T0C35WT18KIoOvXdUsxZuv33lRdc1/OExRyE00TpXV050IUBdsFNPBtk2XAeohVqOML/fdpVcgA2Xh65Wv1MyGSE7ADkvTiwiNR9QtUdm1GuDZxO2FRymhiiSStlUsLvyz4mGbVU4iFAbHF38l6YkHRkC91caZm7SW9muxrF6+cmCgLdT8l0bOAYPj6lErPZ64ojkch+74i8in/hrpsqMb/GSGGISWw==" Oct 30 16:12:27 music go-librespot[15289]: time="2025-10-30T16:12:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:27 music go-librespot[15289]: time="2025-10-30T16:12:27-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:27 music go-librespot[15289]: time="2025-10-30T16:12:27-05:00" level=debug msg="completed challenge" Oct 30 16:12:27 music go-librespot[15289]: time="2025-10-30T16:12:27-05: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 " Oct 30 16:12:27 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:27 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces state update: player Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::getState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand status Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces state update: player Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::getState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand status Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces state update: player Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::getState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand status Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces state update: player Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::getState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand status Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand status took 12 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand status took 10 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand status took 7 milliseconds Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces state update: player Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::getState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand status Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces state update: player Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::getState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand status Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces system playlist update Oct 30 16:12:29 music volumio[962]: info: Ignoring MPD Status Update Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces state update: player Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::getState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand status Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand status took 19 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand playlistinfo took 11 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand playlistinfo took 11 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand playlistinfo took 10 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand status took 8 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand status took 6 milliseconds Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseTrackInfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseTrackInfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseTrackInfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::pushState Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::servicePushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","artist":"WMOT-FM","album":null,"uri":"https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","trackType":""} Oct 30 16:12:29 music volumio[962]: verbose: CURRENT POSITION 0 Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState stateService play Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState currentStatus stop Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::pushState Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::servicePushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","artist":"WMOT-FM","album":null,"uri":"https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","trackType":""} Oct 30 16:12:29 music volumio[962]: verbose: CURRENT POSITION 0 Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState stateService play Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState currentStatus play Oct 30 16:12:29 music volumio[962]: info: Received an update from plugin. extracting info from payload Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::pushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::pushState Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::servicePushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","artist":"WMOT-FM","album":null,"uri":"https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","trackType":""} Oct 30 16:12:29 music volumio[962]: verbose: CURRENT POSITION 0 Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState stateService play Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState currentStatus play Oct 30 16:12:29 music volumio[962]: info: Received an update from plugin. extracting info from payload Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::pushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 56ms Oct 30 16:12:29 music volumio[962]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:29 music volumio[962]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 54ms Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 50ms Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces system playlist update Oct 30 16:12:29 music volumio[962]: info: Ignoring MPD Status Update Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces state update: player Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::getState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand status Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces system playlist update Oct 30 16:12:29 music volumio[962]: info: Ignoring MPD Status Update Oct 30 16:12:29 music volumio[962]: info: Oct 30 16:12:29 music volumio[962]: ---------------------------- MPD announces state update: player Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::getState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand status Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 38ms Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand status took 37 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand playlistinfo took 34 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand playlistinfo took 30 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand playlistinfo took 31 milliseconds Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 14ms Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand status took 12 milliseconds Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 11ms Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand status took 10 milliseconds Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseTrackInfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseTrackInfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseTrackInfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseState Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::pushState Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::servicePushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"96 Kbps","isStreaming":false,"title":"WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","artist":"WMOT-FM","album":null,"uri":"https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","trackType":""} Oct 30 16:12:29 music volumio[962]: verbose: CURRENT POSITION 0 Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState stateService play Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState currentStatus play Oct 30 16:12:29 music volumio[962]: info: Received an update from plugin. extracting info from payload Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::pushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::pushState Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::servicePushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"96 Kbps","isStreaming":false,"title":"WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","artist":"WMOT-FM","album":null,"uri":"https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","trackType":""} Oct 30 16:12:29 music volumio[962]: verbose: CURRENT POSITION 0 Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState stateService play Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState currentStatus play Oct 30 16:12:29 music volumio[962]: info: Received an update from plugin. extracting info from payload Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::pushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::pushState Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::servicePushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"96 Kbps","isStreaming":false,"title":"WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","artist":"WMOT-FM","album":null,"uri":"https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","trackType":""} Oct 30 16:12:29 music volumio[962]: verbose: CURRENT POSITION 0 Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState stateService play Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState currentStatus play Oct 30 16:12:29 music volumio[962]: info: Received an update from plugin. extracting info from payload Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::pushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:29 music volumio[962]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:29 music volumio[962]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 92ms Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 78ms Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 76ms Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand playlistinfo took 29 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand playlistinfo took 27 milliseconds Oct 30 16:12:29 music volumio[962]: info: sendMpdCommand playlistinfo took 28 milliseconds Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseTrackInfo Oct 30 16:12:29 music volumio[962]: verbose: ControllerMpd::parseTrackInfo Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::pushState Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::servicePushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"96 Kbps","isStreaming":false,"title":"WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","artist":"WMOT-FM","album":null,"uri":"https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","trackType":""} Oct 30 16:12:29 music volumio[962]: verbose: CURRENT POSITION 0 Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState stateService play Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState currentStatus play Oct 30 16:12:29 music volumio[962]: info: Received an update from plugin. extracting info from payload Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::pushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::pushState Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::servicePushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"96 Kbps","isStreaming":false,"title":"WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","artist":"WMOT-FM","album":null,"uri":"https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","trackType":""} Oct 30 16:12:29 music volumio[962]: verbose: CURRENT POSITION 0 Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState stateService play Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState currentStatus play Oct 30 16:12:29 music volumio[962]: info: Received an update from plugin. extracting info from payload Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::pushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: info: ControllerMpd::pushState Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::servicePushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"96 Kbps","isStreaming":false,"title":"WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","artist":"WMOT-FM","album":null,"uri":"https://playerservices.streamtheworld.com/api/livestream-redirect/WMOTFM.mp3?DIST=TuneIn&TGT=TuneIn&maxServers=2&gdpr=0&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTc2MTc3MTIwMywiaXNzIjoidGlzcnYifQ.0C9Ol4IG7--PYaUPv4kzXm497HqX8ccFCSqBFZEItXY","trackType":""} Oct 30 16:12:29 music volumio[962]: verbose: CURRENT POSITION 0 Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState stateService play Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::syncState currentStatus play Oct 30 16:12:29 music volumio[962]: info: Received an update from plugin. extracting info from payload Oct 30 16:12:29 music volumio[962]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 30 16:12:29 music volumio[962]: info: CoreStateMachine::pushState Oct 30 16:12:29 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:29 music volumio[962]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:29 music volumio[962]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:29 music volumio[962]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 94ms Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 67ms Oct 30 16:12:29 music volumio[962]: info: ------------------------------ 63ms Oct 30 16:12:29 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:29 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:30 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:30 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8462. Oct 30 16:12:30 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:30 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:30 music go-librespot[15328]: go-librespot daemon starting... Oct 30 16:12:30 music go-librespot[15328]: time="2025-10-30T16:12:30-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:30 music go-librespot[15328]: time="2025-10-30T16:12:30-05:00" level=debug msg="app state loaded" Oct 30 16:12:30 music go-librespot[15328]: time="2025-10-30T16:12:30-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:30 music go-librespot[15328]: time="2025-10-30T16:12:30-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:30 music go-librespot[15328]: time="2025-10-30T16:12:30-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Oct 30 16:12:30 music go-librespot[15328]: time="2025-10-30T16:12:30-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 30 16:12:30 music go-librespot[15328]: time="2025-10-30T16:12:30-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 30 16:12:30 music go-librespot[15328]: time="2025-10-30T16:12:30-05:00" level=info msg="zeroconf server listening on port 36915" Oct 30 16:12:30 music go-librespot[15328]: time="2025-10-30T16:12:30-05:00" level=debug msg="obtained new client token: AABMaPFiz1upO0ItP5jdYgFlj6QIf5bkCp1b4rzWiqvZn/Ssp736sOIZGe0f/OL7p1Us9urmqb+wZB12xFMfcyitn53+KkJmL3UG87Pm3KaBhbhN7uf/d6Y+aiBEMfquWmXGQgW8rPWmX0W/bbmYqI2SFpoEocp6vk8e9c3KtWY1zyvj9+sNdN3DpMbtZPPvrK8qYopIxoPNovBWfm4HMCa7xe+xAqZ223H+RJPZNlNl433+L1XxpEXMpQ==" Oct 30 16:12:31 music go-librespot[15328]: time="2025-10-30T16:12:31-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Oct 30 16:12:31 music go-librespot[15328]: time="2025-10-30T16:12:31-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Oct 30 16:12:31 music go-librespot[15328]: time="2025-10-30T16:12:31-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:31 music go-librespot[15328]: time="2025-10-30T16:12:31-05:00" level=debug msg="completed challenge" Oct 30 16:12:31 music go-librespot[15328]: time="2025-10-30T16:12:31-05: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 " Oct 30 16:12:31 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:31 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:32 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:32 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:34 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:34 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8463. Oct 30 16:12:34 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:34 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:34 music go-librespot[15344]: go-librespot daemon starting... Oct 30 16:12:34 music go-librespot[15344]: time="2025-10-30T16:12:34-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:34 music go-librespot[15344]: time="2025-10-30T16:12:34-05:00" level=debug msg="app state loaded" Oct 30 16:12:34 music go-librespot[15344]: time="2025-10-30T16:12:34-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:34 music go-librespot[15344]: time="2025-10-30T16:12:34-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:34 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:12:34 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:34 music volumio[962]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:34 music volumio[962]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Oct 30 16:12:34 music volumio[962]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Oct 30 16:12:34 music volumio[962]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Oct 30 16:12:34 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:12:34 music volumio[962]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Oct 30 16:12:34 music volumio[962]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Oct 30 16:12:34 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:12:34 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:281:22 Oct 30 16:12:34 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:12:34 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:12:34 music volumio[962]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Oct 30 16:12:34 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:12:34 music volumio[962]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Oct 30 16:12:34 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:284:7 Oct 30 16:12:34 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:12:34 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:12:34 music go-librespot[15344]: time="2025-10-30T16:12:34-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:34 music go-librespot[15344]: time="2025-10-30T16:12:34-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:34 music go-librespot[15344]: time="2025-10-30T16:12:34-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:34 music go-librespot[15344]: time="2025-10-30T16:12:34-05:00" level=info msg="zeroconf server listening on port 43109" Oct 30 16:12:34 music volumio[962]: info: Listing playlists Oct 30 16:12:34 music volumio[962]: info: Listing playlists Oct 30 16:12:35 music go-librespot[15344]: time="2025-10-30T16:12:35-05:00" level=debug msg="obtained new client token: AAAPr4Kcu/o4zSdlWoeyjJ0AfkNJ2P3UoDuROs6nybJVy7JU+pvtRGjZow2UsyAoeCN0Om8gkI8tZnFoho+JnZLk0+2zAXey8nojdM8MpWw4vawaspNAQ0fVyH5eiRPnAeGchmlm5TQq88Qa1PgR/F0Q19k6WuVwxPbjxeTCu7J+rBbfiQ4KniWIIoQZ2TjIrLhOfTSQKvioVkL0xa5JvqhD2EmhNlsFsMURV2jJvlI/mt/h24nQ3Rpt9A==" Oct 30 16:12:35 music go-librespot[15344]: time="2025-10-30T16:12:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:35 music go-librespot[15344]: time="2025-10-30T16:12:35-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:35 music go-librespot[15344]: time="2025-10-30T16:12:35-05:00" level=debug msg="completed challenge" Oct 30 16:12:35 music go-librespot[15344]: time="2025-10-30T16:12:35-05: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 " Oct 30 16:12:35 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:35 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:35 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:35 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:38 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:38 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:38 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:38 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8464. Oct 30 16:12:38 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:38 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:38 music go-librespot[15358]: go-librespot daemon starting... Oct 30 16:12:38 music go-librespot[15358]: time="2025-10-30T16:12:38-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:38 music go-librespot[15358]: time="2025-10-30T16:12:38-05:00" level=debug msg="app state loaded" Oct 30 16:12:38 music go-librespot[15358]: time="2025-10-30T16:12:38-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:38 music go-librespot[15358]: time="2025-10-30T16:12:38-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:38 music go-librespot[15358]: time="2025-10-30T16:12:38-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:38 music go-librespot[15358]: time="2025-10-30T16:12:38-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:38 music go-librespot[15358]: time="2025-10-30T16:12:38-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:38 music go-librespot[15358]: time="2025-10-30T16:12:38-05:00" level=info msg="zeroconf server listening on port 41393" Oct 30 16:12:38 music go-librespot[15358]: time="2025-10-30T16:12:38-05:00" level=debug msg="obtained new client token: AAC3PmptXs59ytcCsParhtbCV1XJ+ZHuxaojE0prVZ8+ezzxZ/CYfLmzP52sv7sCGCexNVvOTr27Zk0ACb5vvxcY1abNHO23cDGrblVTt6NjX0/IGx5CRTTMGI1nVtwMVhBAQ81xyzIrDw47jFtIew6722fr8Lm8v1FRaKdI8B9VD/fRookZLXP6ZGc24ASnK9gRb0XhSkhWWSYDQTNMn/Mu3+CMVXqvmh2v/LsZ3Tz589JAx513kPqCWg==" Oct 30 16:12:39 music go-librespot[15358]: time="2025-10-30T16:12:39-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:39 music go-librespot[15358]: time="2025-10-30T16:12:39-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:39 music go-librespot[15358]: time="2025-10-30T16:12:39-05:00" level=debug msg="completed challenge" Oct 30 16:12:39 music go-librespot[15358]: time="2025-10-30T16:12:39-05: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 " Oct 30 16:12:39 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:39 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:41 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:41 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:42 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:42 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8465. Oct 30 16:12:42 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:42 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:42 music go-librespot[15389]: go-librespot daemon starting... Oct 30 16:12:42 music go-librespot[15389]: time="2025-10-30T16:12:42-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:42 music go-librespot[15389]: time="2025-10-30T16:12:42-05:00" level=debug msg="app state loaded" Oct 30 16:12:42 music go-librespot[15389]: time="2025-10-30T16:12:42-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:42 music go-librespot[15389]: time="2025-10-30T16:12:42-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:42 music go-librespot[15389]: time="2025-10-30T16:12:42-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:42 music go-librespot[15389]: time="2025-10-30T16:12:42-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:42 music go-librespot[15389]: time="2025-10-30T16:12:42-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:42 music go-librespot[15389]: time="2025-10-30T16:12:42-05:00" level=info msg="zeroconf server listening on port 45127" Oct 30 16:12:42 music go-librespot[15389]: time="2025-10-30T16:12:42-05:00" level=debug msg="obtained new client token: AABHzt47PfSdJOhM11tWsk3gVBmLFA7bAAxS6k3ugrnHl5WCig0DHqN8hzbw2olF4FdijKAKL4a9JxGuB7je+rPrqhVVD+QiyoIQubAxq2f7wyLG1VIptdugpdcfs+uAspwsv3ckQq6GQr6bl5vlUKG8QdMOWVJ56gE57EOA7EJ0Fyf74O5f9Qa5MHGr5BG2BOyeX+2y+ueOdOib6FpyyJM0vKIFDD5HHnkMMF4633RP8Gejq7Sc3PxYkg==" Oct 30 16:12:43 music go-librespot[15389]: time="2025-10-30T16:12:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:43 music go-librespot[15389]: time="2025-10-30T16:12:43-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:43 music go-librespot[15389]: time="2025-10-30T16:12:43-05:00" level=debug msg="completed challenge" Oct 30 16:12:43 music go-librespot[15389]: time="2025-10-30T16:12:43-05: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 " Oct 30 16:12:43 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:43 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:44 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:44 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:44 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:12:44 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:44 music volumio[962]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:44 music volumio[962]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Oct 30 16:12:44 music volumio[962]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Oct 30 16:12:44 music volumio[962]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Oct 30 16:12:44 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:12:44 music volumio[962]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Oct 30 16:12:44 music volumio[962]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Oct 30 16:12:44 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:12:44 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:281:22 Oct 30 16:12:44 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:12:44 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:12:44 music volumio[962]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Oct 30 16:12:44 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:12:44 music volumio[962]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Oct 30 16:12:44 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:284:7 Oct 30 16:12:44 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:12:44 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:12:46 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:46 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8466. Oct 30 16:12:46 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:46 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:46 music go-librespot[15408]: go-librespot daemon starting... Oct 30 16:12:46 music go-librespot[15408]: time="2025-10-30T16:12:46-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:46 music go-librespot[15408]: time="2025-10-30T16:12:46-05:00" level=debug msg="app state loaded" Oct 30 16:12:46 music go-librespot[15408]: time="2025-10-30T16:12:46-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:46 music go-librespot[15408]: time="2025-10-30T16:12:46-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:46 music go-librespot[15408]: time="2025-10-30T16:12:46-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:46 music go-librespot[15408]: time="2025-10-30T16:12:46-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:46 music go-librespot[15408]: time="2025-10-30T16:12:46-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:46 music go-librespot[15408]: time="2025-10-30T16:12:46-05:00" level=info msg="zeroconf server listening on port 41223" Oct 30 16:12:46 music go-librespot[15408]: time="2025-10-30T16:12:46-05:00" level=debug msg="obtained new client token: AAA07usUDWlrDeOvK7bFB/fjpTPdzdLv3TDH9giZ1+qwaGSiPPamVx/Ykp7E8eloyZCokGbRHLV8omKfcykovXPKktznmQDiDQOYd8C15Y/gFRx38UG+YmKbxP6ON1XtICShm7cvC8tQvT4+qPCXCn2/IeThS6hARn+Uv01XpC9lpburQ3G8KADLF00nTp59vH5fzW98I1H+22zti1LEF12B19n3KCPEs5RB2edPyFoq6yPEiowZWNJrhw==" Oct 30 16:12:47 music go-librespot[15408]: time="2025-10-30T16:12:47-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:47 music go-librespot[15408]: time="2025-10-30T16:12:47-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:47 music go-librespot[15408]: time="2025-10-30T16:12:47-05:00" level=debug msg="completed challenge" Oct 30 16:12:47 music go-librespot[15408]: time="2025-10-30T16:12:47-05: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 " Oct 30 16:12:47 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:47 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:47 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:47 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:50 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:50 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:50 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:50 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8467. Oct 30 16:12:50 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:50 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:50 music go-librespot[15439]: go-librespot daemon starting... Oct 30 16:12:50 music go-librespot[15439]: time="2025-10-30T16:12:50-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:50 music go-librespot[15439]: time="2025-10-30T16:12:50-05:00" level=debug msg="app state loaded" Oct 30 16:12:50 music go-librespot[15439]: time="2025-10-30T16:12:50-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:50 music go-librespot[15439]: time="2025-10-30T16:12:50-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:50 music go-librespot[15439]: time="2025-10-30T16:12:50-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:50 music go-librespot[15439]: time="2025-10-30T16:12:50-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:50 music go-librespot[15439]: time="2025-10-30T16:12:50-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:50 music go-librespot[15439]: time="2025-10-30T16:12:50-05:00" level=info msg="zeroconf server listening on port 44413" Oct 30 16:12:50 music go-librespot[15439]: time="2025-10-30T16:12:50-05:00" level=debug msg="obtained new client token: AACEoZh8J8V2yLR0vXQqHdc41yyOekh1KrUH3QTZm/wtIldOOCuHCI57MxGiC31daUiQm7j4Sz5JR72Qe4tn++VcBzzoGy47pxTxDJaWil4rVjfGbIO1qk8sr4j8ipnAsqIl+6khJ+shf7XGs1hGLeZ9KJiudWHZpK+1ZqnOyXhuB8/cRbCslMQr0CFT4AUAs64vn7ahCnC806P9BZkAovTnnZ4LqaqRPLHh55H14LoXSOMIRZ0Wd90mpA==" Oct 30 16:12:50 music go-librespot[15439]: time="2025-10-30T16:12:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:51 music go-librespot[15439]: time="2025-10-30T16:12:51-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:51 music go-librespot[15439]: time="2025-10-30T16:12:51-05:00" level=debug msg="completed challenge" Oct 30 16:12:51 music go-librespot[15439]: time="2025-10-30T16:12:51-05: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 " Oct 30 16:12:51 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:51 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:53 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:53 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:54 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:54 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8468. Oct 30 16:12:54 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:54 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:54 music go-librespot[15455]: go-librespot daemon starting... Oct 30 16:12:54 music go-librespot[15455]: time="2025-10-30T16:12:54-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:54 music go-librespot[15455]: time="2025-10-30T16:12:54-05:00" level=debug msg="app state loaded" Oct 30 16:12:54 music go-librespot[15455]: time="2025-10-30T16:12:54-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:54 music go-librespot[15455]: time="2025-10-30T16:12:54-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:54 music go-librespot[15455]: time="2025-10-30T16:12:54-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:54 music go-librespot[15455]: time="2025-10-30T16:12:54-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:54 music go-librespot[15455]: time="2025-10-30T16:12:54-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:54 music go-librespot[15455]: time="2025-10-30T16:12:54-05:00" level=info msg="zeroconf server listening on port 45771" Oct 30 16:12:54 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:12:54 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:12:54 music volumio[962]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Oct 30 16:12:54 music volumio[962]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Oct 30 16:12:54 music volumio[962]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Oct 30 16:12:54 music volumio[962]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Oct 30 16:12:54 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:12:54 music volumio[962]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Oct 30 16:12:54 music volumio[962]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Oct 30 16:12:54 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:12:54 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:281:22 Oct 30 16:12:54 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:12:54 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:12:54 music volumio[962]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Oct 30 16:12:54 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:12:54 music volumio[962]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Oct 30 16:12:54 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:284:7 Oct 30 16:12:54 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:12:54 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:12:54 music volumio[962]: info: Listing playlists Oct 30 16:12:54 music volumio[962]: info: Listing playlists Oct 30 16:12:54 music go-librespot[15455]: time="2025-10-30T16:12:54-05:00" level=debug msg="obtained new client token: AAD6hyYDI7xnUoiDHS6YVsZ4A8UR3dcqn7tiAiJnGf8wtD2aBI4MYYiEOTMS95+OZrV9+Gwb5BBWfZbnk5GegV+LixnaIXNr3F4dWmn0xTy82DBePIskXEhFNax7pNu+Po9DDqVO8XrcpzDoSNuO6BzcO+kUqCi2qtitD1NEnTaLYRufkXMCyfhK/Oy0T0V7PYTurgFMWYWAzj0S3W/+UCwDBsYHWVRLR3LCV1AerGGjm+ZAaAgsPm+a4A==" Oct 30 16:12:55 music go-librespot[15455]: time="2025-10-30T16:12:55-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:55 music go-librespot[15455]: time="2025-10-30T16:12:55-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:55 music go-librespot[15455]: time="2025-10-30T16:12:55-05:00" level=debug msg="completed challenge" Oct 30 16:12:55 music go-librespot[15455]: time="2025-10-30T16:12:55-05: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 " Oct 30 16:12:55 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:55 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:56 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:56 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:12:58 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:12:58 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8469. Oct 30 16:12:58 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:12:58 music systemd[1]: Started go-librespot Daemon. Oct 30 16:12:58 music go-librespot[15471]: go-librespot daemon starting... Oct 30 16:12:58 music go-librespot[15471]: time="2025-10-30T16:12:58-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:12:58 music go-librespot[15471]: time="2025-10-30T16:12:58-05:00" level=debug msg="app state loaded" Oct 30 16:12:58 music go-librespot[15471]: time="2025-10-30T16:12:58-05:00" level=debug msg="stored credentials not found" Oct 30 16:12:58 music go-librespot[15471]: time="2025-10-30T16:12:58-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:12:58 music go-librespot[15471]: time="2025-10-30T16:12:58-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:12:58 music go-librespot[15471]: time="2025-10-30T16:12:58-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:12:58 music go-librespot[15471]: time="2025-10-30T16:12:58-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:12:58 music go-librespot[15471]: time="2025-10-30T16:12:58-05:00" level=info msg="zeroconf server listening on port 37869" Oct 30 16:12:58 music go-librespot[15471]: time="2025-10-30T16:12:58-05:00" level=debug msg="obtained new client token: AACk7w0RR4tj8R0Io2b0v3iVTtXDyrfXgFO5UFBA8bIQ0M7WfDQkVyOpyX1TQtbUOMXPhEthBwcCJTzYPA8pXdimWLIAd7LJGvIBxpB/NuioNPXnfhmWY8Qc5sJtJYL8bS/pMX/OV1TCSkaqqUpDjahoGVt5huaWsOcvMtbj7oMU1fjjLJlTo34Lk718uI+Z6CrpHbqks/rkLVL8FWjSaBhUTZqVrxVNpydg71WxamWrAEy822r+esRpwg==" Oct 30 16:12:59 music go-librespot[15471]: time="2025-10-30T16:12:59-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:12:59 music go-librespot[15471]: time="2025-10-30T16:12:59-05:00" level=debug msg="completed keyexchange" Oct 30 16:12:59 music go-librespot[15471]: time="2025-10-30T16:12:59-05:00" level=debug msg="completed challenge" Oct 30 16:12:59 music go-librespot[15471]: time="2025-10-30T16:12:59-05: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 " Oct 30 16:12:59 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:12:59 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:12:59 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:12:59 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:02 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:02 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:02 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:13:02 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8470. Oct 30 16:13:02 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:13:02 music systemd[1]: Started go-librespot Daemon. Oct 30 16:13:02 music go-librespot[15501]: go-librespot daemon starting... Oct 30 16:13:02 music go-librespot[15501]: time="2025-10-30T16:13:02-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:13:02 music go-librespot[15501]: time="2025-10-30T16:13:02-05:00" level=debug msg="app state loaded" Oct 30 16:13:02 music go-librespot[15501]: time="2025-10-30T16:13:02-05:00" level=debug msg="stored credentials not found" Oct 30 16:13:02 music go-librespot[15501]: time="2025-10-30T16:13:02-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:13:02 music go-librespot[15501]: time="2025-10-30T16:13:02-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Oct 30 16:13:02 music go-librespot[15501]: time="2025-10-30T16:13:02-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 30 16:13:02 music go-librespot[15501]: time="2025-10-30T16:13:02-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 30 16:13:02 music go-librespot[15501]: time="2025-10-30T16:13:02-05:00" level=info msg="zeroconf server listening on port 40311" Oct 30 16:13:02 music go-librespot[15501]: time="2025-10-30T16:13:02-05:00" level=debug msg="obtained new client token: AACW11367gB99syMT0m7KCBDC357UgI9sIAdfu+iuWmZs2V4/v7xmRFFZZA5ZyTgPMLbRkaAdVCV02pv/9udTbwr4wJrZcpBYHThz6SN8NMW9ELDJUKIYvxmusGCAuibKeRVfQ7d1B6Uqg6Va+ami7BORitZxThwnUGcZTz1KYiKAUGjcgRvxKMci6wZkDYBzrHgWjw4wS4cLwjQ0kdTUQrG3xfPzX0po4y9UjtWdntHhtT9nkSUTv7cXQ==" Oct 30 16:13:02 music go-librespot[15501]: time="2025-10-30T16:13:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:13:03 music go-librespot[15501]: time="2025-10-30T16:13:03-05:00" level=debug msg="completed keyexchange" Oct 30 16:13:03 music go-librespot[15501]: time="2025-10-30T16:13:03-05:00" level=debug msg="completed challenge" Oct 30 16:13:03 music go-librespot[15501]: time="2025-10-30T16:13:03-05: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 " Oct 30 16:13:03 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:13:03 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:13:04 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:13:04 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:13:04 music volumio[962]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Oct 30 16:13:04 music volumio[962]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Oct 30 16:13:04 music volumio[962]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Oct 30 16:13:04 music volumio[962]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Oct 30 16:13:04 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:04 music volumio[962]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Oct 30 16:13:04 music volumio[962]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Oct 30 16:13:04 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:04 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:281:22 Oct 30 16:13:04 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:13:04 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:13:04 music volumio[962]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Oct 30 16:13:04 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:04 music volumio[962]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Oct 30 16:13:04 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:284:7 Oct 30 16:13:04 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:13:04 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:13:05 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:05 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:06 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:13:06 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8471. Oct 30 16:13:06 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:13:06 music systemd[1]: Started go-librespot Daemon. Oct 30 16:13:06 music go-librespot[15559]: go-librespot daemon starting... Oct 30 16:13:06 music go-librespot[15559]: time="2025-10-30T16:13:06-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:13:06 music go-librespot[15559]: time="2025-10-30T16:13:06-05:00" level=debug msg="app state loaded" Oct 30 16:13:06 music go-librespot[15559]: time="2025-10-30T16:13:06-05:00" level=debug msg="stored credentials not found" Oct 30 16:13:06 music go-librespot[15559]: time="2025-10-30T16:13:06-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:13:06 music go-librespot[15559]: time="2025-10-30T16:13:06-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:13:06 music go-librespot[15559]: time="2025-10-30T16:13:06-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:13:06 music go-librespot[15559]: time="2025-10-30T16:13:06-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:13:06 music go-librespot[15559]: time="2025-10-30T16:13:06-05:00" level=info msg="zeroconf server listening on port 33329" Oct 30 16:13:06 music go-librespot[15559]: time="2025-10-30T16:13:06-05:00" level=debug msg="obtained new client token: AAA6Usbqaf9yEn3NMAWM1A8U05KrCkTDYyUknooEqHK4IL1yWLYEuqU+FXtiVG6GDXeG+q1sdwTSAh+qNYh+HP/syJbV2gXcYa49R7OF7hLzwTr12tcFtWEN92keyHob58rn5iGuKaWw2IN95RKJZ7w26x/670286NW7eHeuFwufRxOZKlOIekJuTURRL46O7J2be+Q6hbiFKXHETztXsk9y7rHE24aYySRz7OeN/kcR+/vNJmvI1jUOAg==" Oct 30 16:13:07 music go-librespot[15559]: time="2025-10-30T16:13:07-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:13:07 music go-librespot[15559]: time="2025-10-30T16:13:07-05:00" level=debug msg="completed keyexchange" Oct 30 16:13:07 music go-librespot[15559]: time="2025-10-30T16:13:07-05:00" level=debug msg="completed challenge" Oct 30 16:13:07 music go-librespot[15559]: time="2025-10-30T16:13:07-05: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 " Oct 30 16:13:07 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:13:07 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:13:08 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:08 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:10 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:13:10 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8472. Oct 30 16:13:10 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:13:10 music systemd[1]: Started go-librespot Daemon. Oct 30 16:13:10 music go-librespot[15590]: go-librespot daemon starting... Oct 30 16:13:10 music go-librespot[15590]: time="2025-10-30T16:13:10-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:13:10 music go-librespot[15590]: time="2025-10-30T16:13:10-05:00" level=debug msg="app state loaded" Oct 30 16:13:10 music go-librespot[15590]: time="2025-10-30T16:13:10-05:00" level=debug msg="stored credentials not found" Oct 30 16:13:10 music go-librespot[15590]: time="2025-10-30T16:13:10-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:13:10 music go-librespot[15590]: time="2025-10-30T16:13:10-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:13:10 music go-librespot[15590]: time="2025-10-30T16:13:10-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:13:10 music go-librespot[15590]: time="2025-10-30T16:13:10-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:13:10 music go-librespot[15590]: time="2025-10-30T16:13:10-05:00" level=info msg="zeroconf server listening on port 40293" Oct 30 16:13:10 music go-librespot[15590]: time="2025-10-30T16:13:10-05:00" level=debug msg="obtained new client token: AAAmlMmdLzVZL48x0PqrRkAgK1yC18cLPgFklAbaeaPVMHfEDcnoRl7gLaVZxr/ZkvINczKnJTgZva1mmcYhS/Pt9mKqyiPdenjaNhkZfP/lAjY0/JaJy/GyXCFpnjYQTkb7ZPu3ZsSITIssVA6Sy3MGJQTm7zEXRaPuI+ICTOUFX5a0zZsqk0DgZQwGeiPwN0Mr0A0HbtDDkVx40oUpzunbrwxAJ92usKjPDpthqmz6M9GAG79ywLxnvA==" Oct 30 16:13:11 music go-librespot[15590]: time="2025-10-30T16:13:11-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:13:11 music go-librespot[15590]: time="2025-10-30T16:13:11-05:00" level=debug msg="completed keyexchange" Oct 30 16:13:11 music go-librespot[15590]: time="2025-10-30T16:13:11-05:00" level=debug msg="completed challenge" Oct 30 16:13:11 music go-librespot[15590]: time="2025-10-30T16:13:11-05: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 " Oct 30 16:13:11 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:13:11 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:13:11 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:11 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:14 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:14 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:14 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:13:14 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8473. Oct 30 16:13:14 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:13:14 music systemd[1]: Started go-librespot Daemon. Oct 30 16:13:14 music go-librespot[15607]: go-librespot daemon starting... Oct 30 16:13:14 music go-librespot[15607]: time="2025-10-30T16:13:14-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:13:14 music go-librespot[15607]: time="2025-10-30T16:13:14-05:00" level=debug msg="app state loaded" Oct 30 16:13:14 music go-librespot[15607]: time="2025-10-30T16:13:14-05:00" level=debug msg="stored credentials not found" Oct 30 16:13:14 music go-librespot[15607]: time="2025-10-30T16:13:14-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:13:14 music go-librespot[15607]: time="2025-10-30T16:13:14-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:13:14 music go-librespot[15607]: time="2025-10-30T16:13:14-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:13:14 music go-librespot[15607]: time="2025-10-30T16:13:14-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:13:14 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:13:14 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:13:14 music volumio[962]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Oct 30 16:13:14 music volumio[962]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Oct 30 16:13:14 music volumio[962]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Oct 30 16:13:14 music volumio[962]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Oct 30 16:13:14 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:14 music volumio[962]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Oct 30 16:13:14 music volumio[962]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Oct 30 16:13:14 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:14 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:281:22 Oct 30 16:13:14 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:13:14 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:13:14 music volumio[962]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Oct 30 16:13:14 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:14 music volumio[962]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Oct 30 16:13:14 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:284:7 Oct 30 16:13:14 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:13:14 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:13:14 music go-librespot[15607]: time="2025-10-30T16:13:14-05:00" level=info msg="zeroconf server listening on port 39615" Oct 30 16:13:14 music volumio[962]: info: Listing playlists Oct 30 16:13:14 music volumio[962]: info: Listing playlists Oct 30 16:13:14 music go-librespot[15607]: time="2025-10-30T16:13:14-05:00" level=debug msg="obtained new client token: AACLPifLWlmFYYSy655Z63P1TZn9x31hnd7ED0fZCQrs1UMgcaaX5WQ9wvnZs2azQ9aBq7y5sCkl+nfdAa4DP/6E+6Cc4OYRGUNLXd+VTQn0HEd3/GBmX6FPIPCmgPdPXtnuvCgZr3fJLu0KRKX5vhmDDLTkPzdCUDNj5REPRyOjpyO2trhemuVzIjXOhvUaWD9iV+482Psv/nEG1eDY4E1DyEPHU3MAoM4SsgSI8IGvsapu+8CSM7JSgA==" Oct 30 16:13:15 music go-librespot[15607]: time="2025-10-30T16:13:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:13:15 music go-librespot[15607]: time="2025-10-30T16:13:15-05:00" level=debug msg="completed keyexchange" Oct 30 16:13:15 music go-librespot[15607]: time="2025-10-30T16:13:15-05:00" level=debug msg="completed challenge" Oct 30 16:13:15 music go-librespot[15607]: time="2025-10-30T16:13:15-05: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 " Oct 30 16:13:15 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:13:15 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:13:17 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:17 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:18 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:13:18 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8474. Oct 30 16:13:18 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:13:18 music systemd[1]: Started go-librespot Daemon. Oct 30 16:13:18 music go-librespot[15624]: go-librespot daemon starting... Oct 30 16:13:18 music go-librespot[15624]: time="2025-10-30T16:13:18-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:13:18 music go-librespot[15624]: time="2025-10-30T16:13:18-05:00" level=debug msg="app state loaded" Oct 30 16:13:18 music go-librespot[15624]: time="2025-10-30T16:13:18-05:00" level=debug msg="stored credentials not found" Oct 30 16:13:18 music go-librespot[15624]: time="2025-10-30T16:13:18-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:13:18 music go-librespot[15624]: time="2025-10-30T16:13:18-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Oct 30 16:13:18 music go-librespot[15624]: time="2025-10-30T16:13:18-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 30 16:13:18 music go-librespot[15624]: time="2025-10-30T16:13:18-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 30 16:13:18 music go-librespot[15624]: time="2025-10-30T16:13:18-05:00" level=info msg="zeroconf server listening on port 43401" Oct 30 16:13:18 music go-librespot[15624]: time="2025-10-30T16:13:18-05:00" level=debug msg="obtained new client token: AAAd6fbsqzxmBnjoHYSW2zL5pD6pgN+csfBfX12pHRt4+5tIR/B8GlQJAJsVFajVcWmSX3JZcMGR07eJEy/G1I63fDGWgSKnndzGFFzvX9Xv9b/bwX9/aTyVOJKXwCDWRQyIu8Rvpvsp4siyunPJdTkrDDdrj0y4UCLn5Qc+WNzCBJYn240cFB+Dzz1B5DvDv2iiHgvsrMr/YbG7roEJRQbtLHwqDL8iXIylmeg/tIODX0EkWA6n4hcjAw==" Oct 30 16:13:19 music go-librespot[15624]: time="2025-10-30T16:13:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:13:19 music go-librespot[15624]: time="2025-10-30T16:13:19-05:00" level=debug msg="completed keyexchange" Oct 30 16:13:19 music go-librespot[15624]: time="2025-10-30T16:13:19-05:00" level=debug msg="completed challenge" Oct 30 16:13:19 music go-librespot[15624]: time="2025-10-30T16:13:19-05: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 " Oct 30 16:13:19 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:13:19 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:13:20 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:20 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:22 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:13:22 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8475. Oct 30 16:13:22 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:13:22 music systemd[1]: Started go-librespot Daemon. Oct 30 16:13:22 music go-librespot[15655]: go-librespot daemon starting... Oct 30 16:13:22 music go-librespot[15655]: time="2025-10-30T16:13:22-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:13:22 music go-librespot[15655]: time="2025-10-30T16:13:22-05:00" level=debug msg="app state loaded" Oct 30 16:13:22 music go-librespot[15655]: time="2025-10-30T16:13:22-05:00" level=debug msg="stored credentials not found" Oct 30 16:13:22 music go-librespot[15655]: time="2025-10-30T16:13:22-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:13:22 music go-librespot[15655]: time="2025-10-30T16:13:22-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:13:22 music go-librespot[15655]: time="2025-10-30T16:13:22-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:13:22 music go-librespot[15655]: time="2025-10-30T16:13:22-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:13:22 music go-librespot[15655]: time="2025-10-30T16:13:22-05:00" level=info msg="zeroconf server listening on port 34635" Oct 30 16:13:22 music go-librespot[15655]: time="2025-10-30T16:13:22-05:00" level=debug msg="obtained new client token: AAAkYn+0U40RUca5sNdO3IoXMRgkWJlDGxK6J+H6saqoJbWoF1RkEnh537uN6hxDXvDci8lWHy2n6fGNZKruQCd6IyESPYxC8ZZoaTGS/lBbWwIQcENw2kQYpbpfVHaqwFzVl/x9AeFkiRCjmIcMvVJTfM0PCxRficrt3gppxLgbmqONltNmMcpoprOE84M9zI0ipfK6fat18Pe7w4XASYJlPaucu3PIVTc5pNfBHNmyrNFrDZq/Xil/Tg==" Oct 30 16:13:22 music go-librespot[15655]: time="2025-10-30T16:13:22-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:13:23 music go-librespot[15655]: time="2025-10-30T16:13:23-05:00" level=debug msg="completed keyexchange" Oct 30 16:13:23 music go-librespot[15655]: time="2025-10-30T16:13:23-05:00" level=debug msg="completed challenge" Oct 30 16:13:23 music go-librespot[15655]: time="2025-10-30T16:13:23-05: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 " Oct 30 16:13:23 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:13:23 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:13:23 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:23 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:24 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:13:24 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:13:24 music volumio[962]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Oct 30 16:13:24 music volumio[962]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Oct 30 16:13:24 music volumio[962]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Oct 30 16:13:24 music volumio[962]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Oct 30 16:13:24 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:24 music volumio[962]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Oct 30 16:13:24 music volumio[962]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Oct 30 16:13:24 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:24 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:281:22 Oct 30 16:13:24 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:13:24 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:13:24 music volumio[962]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Oct 30 16:13:24 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:24 music volumio[962]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Oct 30 16:13:24 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:284:7 Oct 30 16:13:24 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:13:24 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:13:26 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:26 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:26 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:13:26 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8476. Oct 30 16:13:26 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:13:26 music systemd[1]: Started go-librespot Daemon. Oct 30 16:13:26 music go-librespot[15675]: go-librespot daemon starting... Oct 30 16:13:26 music go-librespot[15675]: time="2025-10-30T16:13:26-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:13:26 music go-librespot[15675]: time="2025-10-30T16:13:26-05:00" level=debug msg="app state loaded" Oct 30 16:13:26 music go-librespot[15675]: time="2025-10-30T16:13:26-05:00" level=debug msg="stored credentials not found" Oct 30 16:13:26 music go-librespot[15675]: time="2025-10-30T16:13:26-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:13:26 music go-librespot[15675]: time="2025-10-30T16:13:26-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:13:26 music go-librespot[15675]: time="2025-10-30T16:13:26-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:13:26 music go-librespot[15675]: time="2025-10-30T16:13:26-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:13:26 music go-librespot[15675]: time="2025-10-30T16:13:26-05:00" level=info msg="zeroconf server listening on port 37283" Oct 30 16:13:26 music go-librespot[15675]: time="2025-10-30T16:13:26-05:00" level=debug msg="obtained new client token: AADpfwCLeXb6umA1i//Rb18oBUMcvhFrYstttoc58NiNaG84o9L/ZgmAyPN9lHJfgMF/6OIFNNoyAagJWTY2JKhP72CAslqYxZcOkUCNpX79LFpJjuOGWQZr/Q+48CfoyxG2gn3V6bjR6gFKdQ4pMrVR6R2OqPsnNSNlobveNi8Sux/kTw93VRDCOc6b/qMVk5l3ry9lgr21YGgkKlOFhEP4tsoVJ+nLQAcdH/dyWAYI5ag/DOzhJOjLow==" Oct 30 16:13:26 music go-librespot[15675]: time="2025-10-30T16:13:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:13:27 music go-librespot[15675]: time="2025-10-30T16:13:27-05:00" level=debug msg="completed keyexchange" Oct 30 16:13:27 music go-librespot[15675]: time="2025-10-30T16:13:27-05:00" level=debug msg="completed challenge" Oct 30 16:13:27 music go-librespot[15675]: time="2025-10-30T16:13:27-05: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 " Oct 30 16:13:27 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:13:27 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:13:29 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:29 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:30 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:13:30 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8477. Oct 30 16:13:30 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:13:30 music systemd[1]: Started go-librespot Daemon. Oct 30 16:13:30 music go-librespot[15706]: go-librespot daemon starting... Oct 30 16:13:30 music go-librespot[15706]: time="2025-10-30T16:13:30-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:13:30 music go-librespot[15706]: time="2025-10-30T16:13:30-05:00" level=debug msg="app state loaded" Oct 30 16:13:30 music go-librespot[15706]: time="2025-10-30T16:13:30-05:00" level=debug msg="stored credentials not found" Oct 30 16:13:30 music go-librespot[15706]: time="2025-10-30T16:13:30-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:13:30 music go-librespot[15706]: time="2025-10-30T16:13:30-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Oct 30 16:13:30 music go-librespot[15706]: time="2025-10-30T16:13:30-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 30 16:13:30 music go-librespot[15706]: time="2025-10-30T16:13:30-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 30 16:13:30 music go-librespot[15706]: time="2025-10-30T16:13:30-05:00" level=info msg="zeroconf server listening on port 42319" Oct 30 16:13:30 music go-librespot[15706]: time="2025-10-30T16:13:30-05:00" level=debug msg="obtained new client token: AACCN2XooKSvibrSpd9IfzY0I4PntPy633LUD6vKiGs/Pb8q79BrsJKBB09MC8TkDdtuolLLWvGVNGVcE0Y3LtDtdwz8C1+abBYj8swWhQ6DOPfgJopuMUaODA1gQlqObIH+/3d19/iMAbimoy5u7xpD51dFSz2Ym+BsQsobkWhYhGT5fnPqQzlvBl0Vgn6eGvTZoTLB2U8hlONKijXItR8ZKZ9zlfGmm+bi0jYGis50oq0Xmk1G7hNyiw==" Oct 30 16:13:31 music go-librespot[15706]: time="2025-10-30T16:13:31-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Oct 30 16:13:31 music go-librespot[15706]: time="2025-10-30T16:13:31-05:00" level=debug msg="completed keyexchange" Oct 30 16:13:31 music go-librespot[15706]: time="2025-10-30T16:13:31-05:00" level=debug msg="completed challenge" Oct 30 16:13:31 music go-librespot[15706]: time="2025-10-30T16:13:31-05: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 " Oct 30 16:13:31 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:13:31 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:13:32 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:32 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:34 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:13:34 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8478. Oct 30 16:13:34 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:13:34 music systemd[1]: Started go-librespot Daemon. Oct 30 16:13:34 music go-librespot[15722]: go-librespot daemon starting... Oct 30 16:13:34 music go-librespot[15722]: time="2025-10-30T16:13:34-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:13:34 music go-librespot[15722]: time="2025-10-30T16:13:34-05:00" level=debug msg="app state loaded" Oct 30 16:13:34 music go-librespot[15722]: time="2025-10-30T16:13:34-05:00" level=debug msg="stored credentials not found" Oct 30 16:13:34 music go-librespot[15722]: time="2025-10-30T16:13:34-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:13:34 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:13:34 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:13:34 music volumio[962]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Oct 30 16:13:34 music volumio[962]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Oct 30 16:13:34 music volumio[962]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Oct 30 16:13:34 music volumio[962]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Oct 30 16:13:34 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:34 music volumio[962]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Oct 30 16:13:34 music volumio[962]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Oct 30 16:13:34 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:34 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:281:22 Oct 30 16:13:34 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:13:34 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:13:34 music volumio[962]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Oct 30 16:13:34 music volumio[962]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 30 16:13:34 music volumio[962]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Oct 30 16:13:34 music volumio[962]: at /volumio/node_modules/express/lib/router/index.js:284:7 Oct 30 16:13:34 music volumio[962]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 30 16:13:34 music volumio[962]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 30 16:13:34 music go-librespot[15722]: time="2025-10-30T16:13:34-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Oct 30 16:13:34 music go-librespot[15722]: time="2025-10-30T16:13:34-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 30 16:13:34 music go-librespot[15722]: time="2025-10-30T16:13:34-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 30 16:13:34 music go-librespot[15722]: time="2025-10-30T16:13:34-05:00" level=info msg="zeroconf server listening on port 40043" Oct 30 16:13:34 music volumio[962]: info: Listing playlists Oct 30 16:13:34 music volumio[962]: info: Listing playlists Oct 30 16:13:35 music go-librespot[15722]: time="2025-10-30T16:13:35-05:00" level=debug msg="obtained new client token: AAA8fXpMiMX5EZWFlQOuLcaYiMWdnisu1zK5f+wtCQ1K1Nebz8Up5Rxt+TxLd2yHBEOSZKuFXn2+Ao3HGo1FiizQl94QheMNQB0UxvIBs/+bUUpmcBtaDe02TusDxdNYlMXpRD4QgIiALoBouVwYWQCG4v4SPVnRBHG9i+LCCa5tf2AP2Ip7zoiJ9eRateoSyz0top6qvT0y7z2eDMmiaFvKwA1RsvUEYqIJsDfHpyk+8cnv6lu7X3I=" Oct 30 16:13:35 music go-librespot[15722]: time="2025-10-30T16:13:35-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Oct 30 16:13:35 music go-librespot[15722]: time="2025-10-30T16:13:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Oct 30 16:13:35 music go-librespot[15722]: time="2025-10-30T16:13:35-05:00" level=debug msg="completed keyexchange" Oct 30 16:13:35 music go-librespot[15722]: time="2025-10-30T16:13:35-05:00" level=debug msg="completed challenge" Oct 30 16:13:35 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:35 music go-librespot[15722]: time="2025-10-30T16:13:35-05:00" level=debug msg="new websocket client" Oct 30 16:13:35 music volumio[962]: info: Connection to go-librespot Websocket established Oct 30 16:13:35 music go-librespot[15722]: time="2025-10-30T16:13:35-05: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 " Oct 30 16:13:35 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 16:13:35 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 16:13:35 music volumio[962]: info: Connection to go-librespot Websocket closed Oct 30 16:13:38 music volumio[962]: info: Getting Spotify volume Oct 30 16:13:38 music volumio[962]: (node:962) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:38 music volumio[962]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Oct 30 16:13:38 music volumio[962]: (node:962) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 710) Oct 30 16:13:38 music volumio[962]: info: Initializing connection to go-librespot Websocket Oct 30 16:13:38 music volumio[962]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 16:13:38 music volumio[962]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 30 16:13:38 music volumio[962]: info: CoreCommandRouter::volumioGetState Oct 30 16:13:38 music volumio[962]: info: CorePlayQueue::getTrack 0 Oct 30 16:13:38 music volumio[962]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 16:13:38 music systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 16:13:38 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8479. Oct 30 16:13:38 music volumio[962]: TypeError: Cannot read property 'name' of undefined Oct 30 16:13:38 music volumio[962]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Oct 30 16:13:38 music volumio[962]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Oct 30 16:13:38 music volumio[962]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:58:38) Oct 30 16:13:38 music volumio[962]: at Socket.emit (events.js:315:20) Oct 30 16:13:38 music volumio[962]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 30 16:13:38 music volumio[962]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Oct 30 16:13:38 music volumio[962]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 16:13:38 music systemd[1]: Stopped go-librespot Daemon. Oct 30 16:13:38 music systemd[1]: Started go-librespot Daemon. Oct 30 16:13:38 music go-librespot[15736]: go-librespot daemon starting... Oct 30 16:13:38 music go-librespot[15736]: time="2025-10-30T16:13:38-05:00" level=info msg="running go-librespot 0.3.2" Oct 30 16:13:38 music go-librespot[15736]: time="2025-10-30T16:13:38-05:00" level=debug msg="app state loaded" Oct 30 16:13:38 music go-librespot[15736]: time="2025-10-30T16:13:38-05:00" level=debug msg="stored credentials not found" Oct 30 16:13:38 music go-librespot[15736]: time="2025-10-30T16:13:38-05:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 16:13:38 music go-librespot[15736]: time="2025-10-30T16:13:38-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 16:13:38 music go-librespot[15736]: time="2025-10-30T16:13:38-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 16:13:38 music go-librespot[15736]: time="2025-10-30T16:13:38-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 16:13:38 music go-librespot[15736]: time="2025-10-30T16:13:38-05:00" level=info msg="zeroconf server listening on port 38597" Oct 30 16:13:39 music sudo[15755]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-10-30 16:12 Oct 30 16:13:39 music sudo[15755]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 16:13:39 music go-librespot[15736]: time="2025-10-30T16:13:39-05:00" level=debug msg="obtained new client token: AAA5vrlzVCUw1EDm77Q2vEvUcfl2t9NYYTVELFCESdblUFWppAZDaDBlufnISTcDxlSps5lor2pviMaGT4DHFtvw3zNV/wlrO/9vQgZNLmNKXMv0vdLo84BYJ4CJxbGFVs44BwQHD/YxcIOrsXk1QIts0Ya5si1tSRAUrHj7Pb7s7UUX+25OtpltDas3DuTIHaGwzuQGtPmgNrnV/eZOD8BX7W93jcR4O2qqV0/iSrvQ5zxEODAZTO2wIA==" Oct 30 16:13:39 music go-librespot[15736]: time="2025-10-30T16:13:39-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"