-- Logs begin at Thu 2019-02-14 02:11:58 PST, end at Fri 2025-06-06 00:17:34 PDT. -- Jun 06 00:16:00 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 95 Jun 06 00:16:00 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:00 volumio-2023 volumio[953]: info: Prefetching next song Jun 06 00:16:00 volumio-2023 volumio[953]: info: Doing Prefetch in UPNP Jun 06 00:16:00 volumio-2023 volumio[953]: verbose: ControllerMpd::sendMpdCommand add "http://10.0.0.153:32469/object/cd2a1aef59f07e270f53/file.flac" Jun 06 00:16:00 volumio-2023 volumio[953]: info: sendMpdCommand add "http://10.0.0.153:32469/object/cd2a1aef59f07e270f53/file.flac" took 1 milliseconds Jun 06 00:16:00 volumio-2023 volumio[953]: verbose: ControllerMpd::sendMpdCommand consume 1 Jun 06 00:16:00 volumio-2023 volumio[953]: info: Jun 06 00:16:00 volumio-2023 volumio[953]: ---------------------------- MPD announces system playlist update Jun 06 00:16:00 volumio-2023 volumio[953]: info: Ignoring MPD Status Update Jun 06 00:16:00 volumio-2023 volumio[953]: info: sendMpdCommand consume 1 took 1 milliseconds Jun 06 00:16:00 volumio-2023 volumio[953]: info: ------------------------------ 1ms Jun 06 00:16:01 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:01 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 568. Jun 06 00:16:01 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:01 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:01 volumio-2023 go-librespot[12922]: go-librespot daemon starting... Jun 06 00:16:01 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:01-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:01 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:01-07:00" level=debug msg="app state loaded" Jun 06 00:16:01 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:01-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:01 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:01-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:01 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:01-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:01 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:01-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:01 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:01-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:01 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:01 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:01-07:00" level=debug msg="new websocket client" Jun 06 00:16:01 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:01-07:00" level=info msg="zeroconf server listening on port 38877" Jun 06 00:16:01 volumio-2023 volumio[953]: info: Connection to go-librespot Websocket established Jun 06 00:16:02 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:02-07:00" level=debug msg="obtained new client token: AADj151w1Q+bm8vaSD1fJ9IO7uPn93MTxtSwb/Yn6Uk0UnGuAnn0pt8Hd/VDaWVmFNUrlC/TsHnQ80IQgrt7GqkF7OMvh8tesacyqXRZ7w3igFyNBYJcbraAM8lUA1rcJp52Kp1/hh66v4tJGfzT2oL7Yw1ku2K0bR65cEZrCsn9UeiJ+wej926IqJVZdie+NACmWCMmBcpHSYGkWzQfC31bnyeYLFPZbqG7/e3X//fFBwl+IeSy+7Hy3Q==" Jun 06 00:16:02 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:02-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:02 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:02-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:02 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:02-07:00" level=debug msg="completed challenge" Jun 06 00:16:02 volumio-2023 go-librespot[12922]: time="2025-06-06T00:16:02-07: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 " Jun 06 00:16:02 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:02 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:02 volumio-2023 volumio[953]: info: Connection to go-librespot Websocket closed Jun 06 00:16:04 volumio-2023 volumio[953]: info: Getting Spotify volume Jun 06 00:16:04 volumio-2023 volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:04 volumio-2023 volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 06 00:16:04 volumio-2023 volumio[953]: (node:953) 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: 119) Jun 06 00:16:04 volumio-2023 volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jun 06 00:16:04 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:04 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 95 Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreStateMachine::startPlaybackTimer Jun 06 00:16:05 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:05 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:05 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:05 volumio-2023 volumio[953]: info: Jun 06 00:16:05 volumio-2023 volumio[953]: ---------------------------- MPD announces system playlist update Jun 06 00:16:05 volumio-2023 volumio[953]: info: Ignoring MPD Status Update Jun 06 00:16:05 volumio-2023 volumio[953]: info: Jun 06 00:16:05 volumio-2023 volumio[953]: ---------------------------- MPD announces state update: player Jun 06 00:16:05 volumio-2023 volumio[953]: info: ControllerMpd::getState Jun 06 00:16:05 volumio-2023 volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 06 00:16:05 volumio-2023 volumio[953]: info: ------------------------------ 2ms Jun 06 00:16:05 volumio-2023 volumio[953]: info: sendMpdCommand status took 1 milliseconds Jun 06 00:16:05 volumio-2023 volumio[953]: verbose: ControllerMpd::parseState Jun 06 00:16:05 volumio-2023 volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 06 00:16:05 volumio-2023 volumio[953]: info: sendMpdCommand playlistinfo took 0 milliseconds Jun 06 00:16:05 volumio-2023 volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 06 00:16:05 volumio-2023 volumio[953]: info: ControllerMpd::pushState Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreCommandRouter::servicePushState Jun 06 00:16:05 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:05 volumio-2023 volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":233,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"612 Kbps","isStreaming":false,"title":"Moments","artist":"Christopher","album":"At Eighteen (Original Television Soundtrack)","uri":"http://10.0.0.153:32469/object/cd2a1aef59f07e270f53/file.flac","trackType":"flac"} Jun 06 00:16:05 volumio-2023 volumio[953]: verbose: CURRENT POSITION 42 Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreStateMachine::syncState stateService play Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 06 00:16:05 volumio-2023 volumio[953]: info: Received an update from plugin. extracting info from payload Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreStateMachine::pushState Jun 06 00:16:05 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioPushState Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreStateMachine::pushState Jun 06 00:16:05 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioPushState Jun 06 00:16:05 volumio-2023 volumio[953]: info: ------------------------------ 10ms Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetQueue Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreStateMachine::getQueue Jun 06 00:16:05 volumio-2023 volumio[953]: info: CorePlayQueue::getQueue Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetQueue Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreStateMachine::getQueue Jun 06 00:16:05 volumio-2023 volumio[953]: info: CorePlayQueue::getQueue Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreStateMachine::pushState Jun 06 00:16:05 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioPushState Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetQueue Jun 06 00:16:05 volumio-2023 volumio[953]: info: CoreStateMachine::getQueue Jun 06 00:16:05 volumio-2023 volumio[953]: info: CorePlayQueue::getQueue Jun 06 00:16:05 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:05 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 569. Jun 06 00:16:05 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:05 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:05 volumio-2023 go-librespot[12932]: go-librespot daemon starting... Jun 06 00:16:05 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:05-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:05 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:05-07:00" level=debug msg="app state loaded" Jun 06 00:16:05 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:05-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:05 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:05-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:06 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:06-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 06 00:16:06 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:06-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 06 00:16:06 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:06-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 06 00:16:06 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:06-07:00" level=info msg="zeroconf server listening on port 39379" Jun 06 00:16:06 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:06-07:00" level=debug msg="obtained new client token: AACpknShEIgPBpSh8OHt3OCBhPeaB5TSHKTn4r+qDKkhoWMY+qsHD+OSEeBqHZs2b4VhJ8JfQtKWW1QAcG77u12Uzx6Csyfp5tOp7kLWQrugo+kDBfJJqN5obH1hzXOqfPw1UJJRnymUxn8Q+27piAg0enS1cxpv/DntIegNXrvbcgRwy4oDtwCCsXDFSO8nR/qGwy6izQhkl6A7HAolyT0DxUgqFJdkHqGvFSvTWBkG//e6wuTJ1Dujbg==" Jun 06 00:16:06 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:06-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:06 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:06-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:06 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:06-07:00" level=debug msg="completed challenge" Jun 06 00:16:07 volumio-2023 go-librespot[12932]: time="2025-06-06T00:16:07-07: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 " Jun 06 00:16:07 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:07 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:08 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:08 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:10 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:10 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 570. Jun 06 00:16:10 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:10 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:10 volumio-2023 go-librespot[12958]: go-librespot daemon starting... Jun 06 00:16:10 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:10-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:10 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:10-07:00" level=debug msg="app state loaded" Jun 06 00:16:10 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:10-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:10 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:10-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:10 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:10-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:10 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:10-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:10 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:10-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:10 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:10-07:00" level=info msg="zeroconf server listening on port 40533" Jun 06 00:16:10 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:10-07:00" level=debug msg="obtained new client token: AABksCfb/Eps1I/SYMfv/HElwvLKTeZsaGkuXTOmAj/G/JG6JTH/u5ZzVwoRLHcDJA7ZDTEgE4Wo5LBNx50mkE4v/blBxi6zpmv73NqugGI40MPEMeuQGP0zAxECxFwfR10ra7D70WlAJyXyiyMe2IhNPvUlPIHHHHeA6PSZMY3XNnLRqYtNp/sTyCaZ3lftzGsqHDyEg3rvXh3tK7T0PAx+1e7DLIUDjfdY+mANDa4SxiX/rTqgIuALPw==" Jun 06 00:16:10 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:10-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:11 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:11-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:11 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:11-07:00" level=debug msg="completed challenge" Jun 06 00:16:11 volumio-2023 go-librespot[12958]: time="2025-06-06T00:16:11-07: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 " Jun 06 00:16:11 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:11 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:11 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:11 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:14 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:14 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 571. Jun 06 00:16:14 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:14 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:14 volumio-2023 go-librespot[12967]: go-librespot daemon starting... Jun 06 00:16:14 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:14-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:14 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:14-07:00" level=debug msg="app state loaded" Jun 06 00:16:14 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:14-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:14 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:14-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:14 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:14 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:14-07:00" level=debug msg="new websocket client" Jun 06 00:16:14 volumio-2023 volumio[953]: info: Connection to go-librespot Websocket established Jun 06 00:16:14 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:14-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:14 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:14-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:14 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:14-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:14 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:14-07:00" level=info msg="zeroconf server listening on port 38111" Jun 06 00:16:15 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:15-07:00" level=debug msg="obtained new client token: AADCAABIZlQeUxmKVqepXSgiAdUQZk437qKBlZ/j8QBA9b1yDkJqqtr6OR/yQR8Jso68lSFQG0Q0nd0YkFzgs46DHb5+IEngPo6vyCH+TCVLH4nwuLUr2LRf13iA51HWODSpKuN7TPXszNqZy/Vwr0SkgduMphF7dk6TI4xsuV6r7fudQdTojP1pZ6vdWSIG7IQhZdFIqqZouWYu+6/xYjuHKnQr9/E/RG3Q/vMcfXm+cC61wSRhchE=" Jun 06 00:16:15 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:15-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:15 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:15-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:15 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:15-07:00" level=debug msg="completed challenge" Jun 06 00:16:15 volumio-2023 go-librespot[12967]: time="2025-06-06T00:16:15-07: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 " Jun 06 00:16:15 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:15 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:15 volumio-2023 volumio[953]: info: Connection to go-librespot Websocket closed Jun 06 00:16:17 volumio-2023 volumio[953]: info: Getting Spotify volume Jun 06 00:16:17 volumio-2023 volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:17 volumio-2023 volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 06 00:16:17 volumio-2023 volumio[953]: (node:953) 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: 120) Jun 06 00:16:17 volumio-2023 volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Jun 06 00:16:17 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:17 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:18 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:18 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:18 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:18 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 572. Jun 06 00:16:18 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:18 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:18 volumio-2023 go-librespot[12976]: go-librespot daemon starting... Jun 06 00:16:18 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:18-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:18 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:18-07:00" level=debug msg="app state loaded" Jun 06 00:16:18 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:18-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:18 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:18-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:18 volumio-2023 sudo[12999]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 06 00:16:18 volumio-2023 sudo[13001]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 06 00:16:18 volumio-2023 sudo[13001]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 00:16:18 volumio-2023 sudo[12999]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 00:16:18 volumio-2023 sudo[12999]: pam_unix(sudo:session): session closed for user root Jun 06 00:16:18 volumio-2023 sudo[13001]: pam_unix(sudo:session): session closed for user root Jun 06 00:16:18 volumio-2023 volumio[953]: verbose: New Socket.io Connection to 10.0.0.26 from 10.0.0.153 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/137.0.0.0 Safari/537.36 Edg/137.0.0.0 Engine version: 3 Transport: polling Total Clients: 6 Jun 06 00:16:18 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:18-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:18 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:18-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:18 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:18-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:18 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:18-07:00" level=info msg="zeroconf server listening on port 36955" Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 06 00:16:19 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:19-07:00" level=debug msg="obtained new client token: AAANGA7TKUz99xtRBtmu0zCEvlcqb8OBYGElMc1yClpXeNahM3tQ/p4+ZGmYCUVexWuMu0TWjfafDqKmgvNFI/xo78bWW/RqZYsxVqLJXPtYF/uNjJR0GUjksncY3zPs1l1w5VT0E8/0TiQdEtRVcVOislYiV0cBprq8esc9gWaUky6NJ00VTW0joOW3PdSwGsZqYVapiTvtpC9diYk39vZQF0bx9w9T9FjQL203hmctXbmuY8UDZ6w=" Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 06 00:16:19 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:19-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:19 volumio-2023 sudo[13005]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 06 00:16:19 volumio-2023 sudo[13005]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 00:16:19 volumio-2023 sudo[13005]: pam_unix(sudo:session): session closed for user root Jun 06 00:16:19 volumio-2023 sudo[13008]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 06 00:16:19 volumio-2023 sudo[13008]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 00:16:19 volumio-2023 sudo[13008]: pam_unix(sudo:session): session closed for user root Jun 06 00:16:19 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:19-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:19 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:19-07:00" level=debug msg="completed challenge" Jun 06 00:16:19 volumio-2023 volumio[953]: verbose: New Socket.io Connection to 10.0.0.26 from 10.0.0.153 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/137.0.0.0 Safari/537.36 Edg/137.0.0.0 Engine version: 3 Transport: polling Total Clients: 7 Jun 06 00:16:19 volumio-2023 go-librespot[12976]: time="2025-06-06T00:16:19-07: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 " Jun 06 00:16:19 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:19 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetVisibleSources Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:19 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetQueue Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreStateMachine::getQueue Jun 06 00:16:19 volumio-2023 volumio[953]: info: CorePlayQueue::getQueue Jun 06 00:16:19 volumio-2023 volumio[953]: info: Listing playlists Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 06 00:16:19 volumio-2023 volumio[953]: info: Received Get System Info Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 06 00:16:19 volumio-2023 volumio[953]: info: Discovery: Getting this device information Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:19 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:19 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 06 00:16:19 volumio-2023 volumio[953]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 06 00:16:19 volumio-2023 volumio[953]: info: FusionDsp - Jun 06 00:16:19 volumio-2023 volumio[953]: info: FusionDsp - undefined Jun 06 00:16:20 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 06 00:16:21 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jun 06 00:16:21 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 06 00:16:21 volumio-2023 volumio[953]: info: Received Get System Info Jun 06 00:16:21 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 06 00:16:21 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 06 00:16:21 volumio-2023 volumio[953]: info: Discovery: Getting this device information Jun 06 00:16:21 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:21 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:21 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 06 00:16:21 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:21 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:22 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 06 00:16:22 volumio-2023 volumio[953]: info: Received Get System Info Jun 06 00:16:22 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 06 00:16:22 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 06 00:16:22 volumio-2023 volumio[953]: info: Discovery: Getting this device information Jun 06 00:16:22 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:22 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:22 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 06 00:16:22 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:22 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 573. Jun 06 00:16:22 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:22 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:22 volumio-2023 go-librespot[13011]: go-librespot daemon starting... Jun 06 00:16:22 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:22-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:22 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:22-07:00" level=debug msg="app state loaded" Jun 06 00:16:22 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:22-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:22 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:22-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:22 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:22-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:22 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:22-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:22 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:22-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:22 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:22-07:00" level=info msg="zeroconf server listening on port 44095" Jun 06 00:16:23 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:23-07:00" level=debug msg="obtained new client token: AABfcg/bycUAHVS9Ma9xpLlP9W+aP5jT/14PYMnqXd4zvpI41sEvvwDnD98N2Lcw4V+bx+ruxwcGlPKVJ4dgv1dwACTX8vcYUCLBpZfFFhgNzsYr8IHQTL1n2FaUZloL60Gl+CrAekLZrAAHGQxtnQuLMN7nVPFkxDDiE41Oy0KJd0zGFQioAh6NvH6yyhGxypwqyx1TN4oHskcC3/K21eSEItdaevQiV57K+pAaLz++YKG2hwXsKh0=" Jun 06 00:16:23 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:23-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:23 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:23-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:23 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:23-07:00" level=debug msg="completed challenge" Jun 06 00:16:24 volumio-2023 go-librespot[13011]: time="2025-06-06T00:16:24-07: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 " Jun 06 00:16:24 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:24 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:24 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:24 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:27 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:27 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 574. Jun 06 00:16:27 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:27 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:27 volumio-2023 go-librespot[13064]: go-librespot daemon starting... Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=debug msg="app state loaded" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=info msg="zeroconf server listening on port 32999" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=debug msg="obtained new client token: AACvw0F6hHIbIeMAhZpj/DCutFXwqmbSmkQf1OqgCk/45MLNzbn3Mci+IC8Z/kyBEIVr2yPHo+ne+QVWVZ22OAGscnrA34z7BlN9TpglM2IdycePwUUW1rIjynjK9G0OsgcVojl4rXrbnFABCt0TAAkKVS1bLsu32y65i5CFilM1aFInWIIbsSzGMZh2ISKMsOKXSnrRAjnqqbOM0sDsrrCGcl795KYtNW9Ga+5TD4mKaO09o2F76WTHzw==" Jun 06 00:16:27 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=debug msg="new websocket client" Jun 06 00:16:27 volumio-2023 volumio[953]: info: Connection to go-librespot Websocket established Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07:00" level=debug msg="completed challenge" Jun 06 00:16:27 volumio-2023 go-librespot[13064]: time="2025-06-06T00:16:27-07: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 " Jun 06 00:16:27 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:27 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:27 volumio-2023 volumio[953]: info: Connection to go-librespot Websocket closed Jun 06 00:16:29 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioPause Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreStateMachine::pause Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreStateMachine::stPlaybackTimer Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreStateMachine::servicePause Jun 06 00:16:30 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreCommandRouter::servicePause Jun 06 00:16:30 volumio-2023 volumio[953]: info: [1749194190309] ControllerUPNPBrowser::pause Jun 06 00:16:30 volumio-2023 volumio[953]: verbose: ControllerMpd::sendMpdCommand pause Jun 06 00:16:30 volumio-2023 volumio[953]: info: sendMpdCommand pause took 1 milliseconds Jun 06 00:16:30 volumio-2023 volumio[953]: info: Jun 06 00:16:30 volumio-2023 volumio[953]: ---------------------------- MPD announces state update: player Jun 06 00:16:30 volumio-2023 volumio[953]: info: ControllerMpd::getState Jun 06 00:16:30 volumio-2023 volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 06 00:16:30 volumio-2023 volumio[953]: info: sendMpdCommand status took 0 milliseconds Jun 06 00:16:30 volumio-2023 volumio[953]: verbose: ControllerMpd::parseState Jun 06 00:16:30 volumio-2023 volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 06 00:16:30 volumio-2023 volumio[953]: info: sendMpdCommand playlistinfo took 0 milliseconds Jun 06 00:16:30 volumio-2023 volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 06 00:16:30 volumio-2023 volumio[953]: info: ControllerMpd::pushState Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreCommandRouter::servicePushState Jun 06 00:16:30 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:30 volumio-2023 volumio[953]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":24550,"duration":233,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"812 Kbps","isStreaming":false,"title":"Moments","artist":"Christopher","album":"At Eighteen (Original Television Soundtrack)","uri":"http://10.0.0.153:32469/object/cd2a1aef59f07e270f53/file.flac","trackType":"flac"} Jun 06 00:16:30 volumio-2023 volumio[953]: verbose: CURRENT POSITION 42 Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreStateMachine::syncState stateService pause Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreStateMachine::syncState currentStatus pause Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreStateMachine::pushState Jun 06 00:16:30 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioPushState Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreStateMachine::stPlaybackTimer Jun 06 00:16:30 volumio-2023 volumio[953]: info: ------------------------------ 7ms Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetQueue Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreStateMachine::getQueue Jun 06 00:16:30 volumio-2023 volumio[953]: info: CorePlayQueue::getQueue Jun 06 00:16:30 volumio-2023 volumio[953]: info: Getting Spotify volume Jun 06 00:16:30 volumio-2023 volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:30 volumio-2023 volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 06 00:16:30 volumio-2023 volumio[953]: (node:953) 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: 121) Jun 06 00:16:30 volumio-2023 volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 06 00:16:30 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:30 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:30 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:30 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:30 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:30 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 575. Jun 06 00:16:30 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:30 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:30 volumio-2023 go-librespot[13087]: go-librespot daemon starting... Jun 06 00:16:30 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:30-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:30 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:30-07:00" level=debug msg="app state loaded" Jun 06 00:16:30 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:30-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:30 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:30-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:31 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:31-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:31 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:31-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:31 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:31-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:31 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:31-07:00" level=info msg="zeroconf server listening on port 33689" Jun 06 00:16:31 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:31-07:00" level=debug msg="obtained new client token: AAAaTEkZcruH01VD//RE7CjUckqK77VFlWuV07sg1WgazXE9qMRI4BANX1g4WLLr2USU6LQFI9/57F7MFrhp5HZ7rsoS6YrdUYM7Z8MZIcBTku8JbH4lVbnGJ3wsZFhBBr4Iue+9ZJd31spvWJm1910HKbxlC15Nbs8zZn34u5cs9zGPf8XkRwiuw3fzF8jY6zzF3r8gq6ZCbCLK/PU+R9q0FxrdzaRnOv431Z7wA+JLUtytobLSjVH5ow==" Jun 06 00:16:31 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:31-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:31 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:31-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:31 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:31-07:00" level=debug msg="completed challenge" Jun 06 00:16:31 volumio-2023 go-librespot[13087]: time="2025-06-06T00:16:31-07: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 " Jun 06 00:16:31 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:31 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:33 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:33 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:34 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:34 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 576. Jun 06 00:16:34 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:34 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:34 volumio-2023 go-librespot[13102]: go-librespot daemon starting... Jun 06 00:16:34 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:34-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:34 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:34-07:00" level=debug msg="app state loaded" Jun 06 00:16:34 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:34-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:34 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:34-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:34 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:34-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:34 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:34-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:34 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:34-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:34 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:34-07:00" level=info msg="zeroconf server listening on port 44999" Jun 06 00:16:35 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:35-07:00" level=debug msg="obtained new client token: AAC8zjlCSCFETCnNjRSD357ehSqh0yWWWhuIZkJEdf1T5M16MdHbjL/5exIZvexOKApoEdBtj2wu3fP6IQiO9ffVsZc+WthiaMmM8PVbvOawcXIu1uNKn98wz76lil7My7S+Dwa3MyjKqVFQG98k38F9hjpDsjkXxt715I/R8gvD8KTs5JlIAKAclIjBqenbi7ON7NijTwYFKqtM3V5Q83dgtX2v/l4K7ldYkxMCtvbgYDsUbVUai/U=" Jun 06 00:16:35 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:35-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:35 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:35-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:35 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:35-07:00" level=debug msg="completed challenge" Jun 06 00:16:35 volumio-2023 go-librespot[13102]: time="2025-06-06T00:16:35-07: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 " Jun 06 00:16:35 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:35 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:35 volumio-2023 sudo[13113]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 06 00:16:35 volumio-2023 sudo[13113]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 00:16:35 volumio-2023 sudo[13113]: pam_unix(sudo:session): session closed for user root Jun 06 00:16:35 volumio-2023 sudo[13116]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 06 00:16:35 volumio-2023 sudo[13116]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 00:16:35 volumio-2023 sudo[13116]: pam_unix(sudo:session): session closed for user root Jun 06 00:16:35 volumio-2023 volumio[953]: verbose: New Socket.io Connection to 10.0.0.26 from 10.0.0.153 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/137.0.0.0 Safari/537.36 Edg/137.0.0.0 Engine version: 3 Transport: polling Total Clients: 7 Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetVisibleSources Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:35 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetQueue Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreStateMachine::getQueue Jun 06 00:16:35 volumio-2023 volumio[953]: info: CorePlayQueue::getQueue Jun 06 00:16:35 volumio-2023 volumio[953]: info: Listing playlists Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 06 00:16:35 volumio-2023 volumio[953]: info: Received Get System Info Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 06 00:16:35 volumio-2023 volumio[953]: info: Discovery: Getting this device information Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:35 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:35 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 06 00:16:35 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 06 00:16:36 volumio-2023 volumio[953]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 06 00:16:36 volumio-2023 volumio[953]: info: FusionDsp - Jun 06 00:16:36 volumio-2023 volumio[953]: info: FusionDsp - undefined Jun 06 00:16:36 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:36 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:37 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jun 06 00:16:37 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 06 00:16:37 volumio-2023 volumio[953]: info: Received Get System Info Jun 06 00:16:37 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 06 00:16:37 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 06 00:16:37 volumio-2023 volumio[953]: info: Discovery: Getting this device information Jun 06 00:16:37 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:37 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:37 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 06 00:16:38 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 06 00:16:38 volumio-2023 volumio[953]: info: Received Get System Info Jun 06 00:16:38 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 06 00:16:38 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 06 00:16:38 volumio-2023 volumio[953]: info: Discovery: Getting this device information Jun 06 00:16:38 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:38 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:38 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 06 00:16:38 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:38 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 577. Jun 06 00:16:38 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:38 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:38 volumio-2023 go-librespot[13118]: go-librespot daemon starting... Jun 06 00:16:38 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:38-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:38 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:38-07:00" level=debug msg="app state loaded" Jun 06 00:16:38 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:38-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:38 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:38-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:38 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:38-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:38 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:38-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:38 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:38-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:38 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:38-07:00" level=info msg="zeroconf server listening on port 33167" Jun 06 00:16:38 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:38-07:00" level=debug msg="obtained new client token: AAABO9/g9w+9Pr4mpwp2fgoBeball5Na1C1CFz+qIAst+tK2V6hzsprevg1csK5doP65optM0K4+BuY3sBD9i2ejq5r2tVPV4O/dBUKx206CHxxZ/WRyl3jzCH9W8ZHj83jJ5bRokSTny3+T75UPFenwvJcDrkKVjd1k7+FETflyKAT7QGbR3WtQljYyU9wM2VpTmdovB88ImBfjred8sx3UEDnnRrJ0V+lq1qW0hX2H0Z0CpbcNITzbgQ==" Jun 06 00:16:38 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:38-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:39 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:39-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:39 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:39-07:00" level=debug msg="completed challenge" Jun 06 00:16:39 volumio-2023 go-librespot[13118]: time="2025-06-06T00:16:39-07: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 " Jun 06 00:16:39 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:39 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:39 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:39 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:42 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:42 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 578. Jun 06 00:16:42 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:42 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:42 volumio-2023 go-librespot[13141]: go-librespot daemon starting... Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=debug msg="app state loaded" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=info msg="zeroconf server listening on port 43517" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=debug msg="obtained new client token: AADGseC7HqMbv2BUoK61ieJoPRx+j/6YY8YsdgZtUZF8BTnuN3l9Budpqu8vPuUKiSwu47AwjCjQmVKOlyOivHJCBwhSQVbsdmjPO6Kukwv9U7+G75ABjdWNrYM6D41c45VorbqM6EFZicV1dFqM37Gfh7XaIjLq10F7RWCidkff4t3UiR/Mch4UlKSMPNaE+m+KUKRz/kFbnTIc7uR2Cd0PR4bTIkfKA30IAF7GL0ttb+XkfRdjOmffTQ==" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=debug msg="completed challenge" Jun 06 00:16:42 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07:00" level=debug msg="new websocket client" Jun 06 00:16:42 volumio-2023 volumio[953]: info: Connection to go-librespot Websocket established Jun 06 00:16:42 volumio-2023 go-librespot[13141]: time="2025-06-06T00:16:42-07: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 " Jun 06 00:16:42 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:42 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:42 volumio-2023 volumio[953]: info: Connection to go-librespot Websocket closed Jun 06 00:16:43 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: plexamp , handleBrowseUri Jun 06 00:16:43 volumio-2023 volumio[953]: info: plexamp Jun 06 00:16:43 volumio-2023 volumio[953]: info: Preload queue cleared Jun 06 00:16:45 volumio-2023 volumio[953]: info: Getting Spotify volume Jun 06 00:16:45 volumio-2023 volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:45 volumio-2023 volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 06 00:16:45 volumio-2023 volumio[953]: (node:953) 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: 122) Jun 06 00:16:45 volumio-2023 volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 06 00:16:45 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:45 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:45 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:45 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:45 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 06 00:16:45 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:45 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 579. Jun 06 00:16:45 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:45 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:45 volumio-2023 go-librespot[13149]: go-librespot daemon starting... Jun 06 00:16:45 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:45-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:45 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:45-07:00" level=debug msg="app state loaded" Jun 06 00:16:45 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:45-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:45 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:45-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:46 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:46-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:46 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:46-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:46 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:46-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:46 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:46-07:00" level=info msg="zeroconf server listening on port 44917" Jun 06 00:16:46 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:46-07:00" level=debug msg="obtained new client token: AAAuulKtPjLyHdr5w/JF2SUZBXL+AZxoX5ChaLky2apGDnWAjZiWVFjWpX4Uu/a5Q43Zv1CDTDTZz0iPyeStONvkk94i5QvH9qlfFXR/TTfoRyqNnHisE4nhq2sybY49HfNwBaA0tMt1qOHreaHRJYMKvGQlIk0pEKGpSP7nVXax0FJ3JZcB98PVoR4d93rdW+EmuBuIZbF/QO7KvgDsllxbKc4IlCPo4FvigHAq6ONyd3Rv4d+dlNjR3Q==" Jun 06 00:16:46 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:46-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:46 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:46-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:46 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:46-07:00" level=debug msg="completed challenge" Jun 06 00:16:46 volumio-2023 go-librespot[13149]: time="2025-06-06T00:16:46-07: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 " Jun 06 00:16:46 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:46 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:46 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: plexamp , handleBrowseUri Jun 06 00:16:46 volumio-2023 volumio[953]: info: plexamp/playlists Jun 06 00:16:46 volumio-2023 volumio[953]: info: PlexAmp: Error Error: Plex Server didnt respond with a valid 2xx status code, response code: 404 Jun 06 00:16:48 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:48 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:49 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:49 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 580. Jun 06 00:16:49 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:49 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:49 volumio-2023 go-librespot[13175]: go-librespot daemon starting... Jun 06 00:16:49 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:49-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:49 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:49-07:00" level=debug msg="app state loaded" Jun 06 00:16:49 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:49-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:49 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:49-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:50 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:50-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:50 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:50-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:50 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:50-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:50 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:50-07:00" level=info msg="zeroconf server listening on port 44997" Jun 06 00:16:50 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:50-07:00" level=debug msg="obtained new client token: AABqRpgIeKbLNkgl1txTZgepnEgdLxTKyy7FW9SZBZUCgS6B6skKRL3RtAvZVdNXnxpn8jgM2o3aaRcpNFpk49XEjrPnb5/rmuaKmE6LF7706gSi5Xygr4T5sqUi4jPiylVp//LldmfdeAfbcm3bOdRSqm6ZQVBD/w85vlLY4BewIX27RKyt8Lz8v+Y9IDyZhlvwg6OSqFKp0PpE7wLO2Z/xfamax4LfUOXi5uiqwglr8b+ydK4jt1nrkQ==" Jun 06 00:16:50 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:50-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:50 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:50-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:50 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:50-07:00" level=debug msg="completed challenge" Jun 06 00:16:50 volumio-2023 go-librespot[13175]: time="2025-06-06T00:16:50-07: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 " Jun 06 00:16:50 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:50 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:51 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:51 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:53 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:53 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 581. Jun 06 00:16:53 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:53 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:53 volumio-2023 go-librespot[13184]: go-librespot daemon starting... Jun 06 00:16:53 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:53-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:53 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:53-07:00" level=debug msg="app state loaded" Jun 06 00:16:53 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:53-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:53 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:53-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:53 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:53-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:53 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:53-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:53 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:53-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:53 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:53-07:00" level=info msg="zeroconf server listening on port 41939" Jun 06 00:16:54 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:54-07:00" level=debug msg="obtained new client token: AAAtBqZYRkhi951gyQY6ziYUFtRfn6CkUtrC6eMWVeFyAPOhH7naYh7RKU9n3WBY3aO1TGlx6OWNn4735SYSv7HmAYmAXqDwjaUC3R4cdctMpK3g6P5rsRHR+fpavNqiOPCxxg5fXNMMDpoE0xWRJ/ektvCSD/RIVQasiBUukaCwWmbOm9aPj5xXKjMhQn7A7OvQc+7a4l9JsAGL4eutUi6qN1Bcrh6IsbUZGip6gnPQm1ZWl1CYguI=" Jun 06 00:16:54 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:54-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:54 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 06 00:16:54 volumio-2023 volumio[953]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jun 06 00:16:54 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jun 06 00:16:54 volumio-2023 volumio[953]: info: Received Get System Version Jun 06 00:16:54 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 06 00:16:54 volumio-2023 volumio[953]: info: Received Get System Info Jun 06 00:16:54 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 06 00:16:54 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 06 00:16:54 volumio-2023 volumio[953]: info: Discovery: Getting this device information Jun 06 00:16:54 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:16:54 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:16:54 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 06 00:16:54 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:54-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:54 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:54-07:00" level=debug msg="completed challenge" Jun 06 00:16:54 volumio-2023 go-librespot[13184]: time="2025-06-06T00:16:54-07: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 " Jun 06 00:16:54 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:54 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:54 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:54 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:16:57 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:16:57 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 582. Jun 06 00:16:57 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:16:57 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:16:57 volumio-2023 go-librespot[13192]: go-librespot daemon starting... Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=debug msg="app state loaded" Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=debug msg="stored credentials not found" Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=info msg="zeroconf server listening on port 33371" Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=debug msg="obtained new client token: AABXlNYFB8UgPruq9nbOOR+ytC+ziK97m+eGS3nokc0SX8atWRWWUJE127xQqrS1Hd1EX9URKn4CN6vUkDip3pbCPbXqWbD2rH1tMfsdjVnN0ivHiLppVdQaUw7iecs5ulX4BZ4Pje9T0ovXdwCY0BkL+UPmJqKh9vuF2fq6nmuXEfRcaWTd1iKBD3T7nFCVCJHo+kqQ3jhThHHbiArp2dyeD/NKNH6HROUlf5nIsybI8gZQInkfjg4kiQ==" Jun 06 00:16:57 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=debug msg="new websocket client" Jun 06 00:16:57 volumio-2023 volumio[953]: info: Connection to go-librespot Websocket established Jun 06 00:16:57 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:57-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:16:58 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:58-07:00" level=debug msg="completed keyexchange" Jun 06 00:16:58 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:58-07:00" level=debug msg="completed challenge" Jun 06 00:16:58 volumio-2023 go-librespot[13192]: time="2025-06-06T00:16:58-07: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 " Jun 06 00:16:58 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:16:58 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:16:58 volumio-2023 volumio[953]: info: Connection to go-librespot Websocket closed Jun 06 00:17:00 volumio-2023 volumio[953]: info: Getting Spotify volume Jun 06 00:17:00 volumio-2023 volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:00 volumio-2023 volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 06 00:17:00 volumio-2023 volumio[953]: (node:953) 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: 123) Jun 06 00:17:00 volumio-2023 volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jun 06 00:17:00 volumio-2023 volumio[953]: info: CoreCommandRouter::volumioGetState Jun 06 00:17:00 volumio-2023 volumio[953]: info: CorePlayQueue::getTrack 42 Jun 06 00:17:01 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:01 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:01 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:17:01 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 583. Jun 06 00:17:01 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:17:01 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:17:01 volumio-2023 go-librespot[13216]: go-librespot daemon starting... Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=debug msg="app state loaded" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=debug msg="stored credentials not found" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=info msg="zeroconf server listening on port 36431" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=debug msg="obtained new client token: AADEdMBmlHqXUCcp7j8LGeXi16DSUbvc1JKSAzx/LjaZVYdgYmtl1BiVfHS7m1h2jMkDgk5VJqzuN4LbSnAIlaw17FcO+Ewp2tcMqN5F70X6Q9vMF7E1q6j+Z7dJC7JhSzFNcQQ+kcOl3Y6oBqNuN8/KZlC4c58ycVizvG2Q/7aWhWWmYm7u9c4MO3HpGUKW/b7usnId4qpzGmY7dd8/cd/TvkG+aW1KTcqVdy7q28Urn9cnENGcaPLugw==" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=debug msg="completed keyexchange" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07:00" level=debug msg="completed challenge" Jun 06 00:17:01 volumio-2023 go-librespot[13216]: time="2025-06-06T00:17:01-07: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 " Jun 06 00:17:01 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:17:01 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:17:04 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:04 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:05 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:17:05 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 584. Jun 06 00:17:05 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:17:05 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:17:05 volumio-2023 go-librespot[13225]: go-librespot daemon starting... Jun 06 00:17:05 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:05-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:17:05 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:05-07:00" level=debug msg="app state loaded" Jun 06 00:17:05 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:05-07:00" level=debug msg="stored credentials not found" Jun 06 00:17:05 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:05-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:17:05 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:05-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:17:05 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:05-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:17:05 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:05-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:17:05 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:05-07:00" level=info msg="zeroconf server listening on port 42299" Jun 06 00:17:05 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:05-07:00" level=debug msg="obtained new client token: AAD4wPn/U5VT6P48+VHkREJgDZhqjhSy8gMyTwoup3uzKu4rQvQ6OMWi7hNYc7BqOOuvvqu70BfI+ElMBeBH9irKhG1MeKDFwddgMOngpYHkhrS3UFtpZWKjM9cyzL246wG9OZylDrJQiIiaz6x8o2M2qdhbDFtJboVCi98qIqWwsuQ0hunG3B9TCc0odeAf27zH+TYuW9QMtUlQ2NIP9UwSzIcNkrNf1HV0XpRaTFrwC4u+pVokQT27mw==" Jun 06 00:17:05 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:05-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:17:06 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:06-07:00" level=debug msg="completed keyexchange" Jun 06 00:17:06 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:06-07:00" level=debug msg="completed challenge" Jun 06 00:17:06 volumio-2023 go-librespot[13225]: time="2025-06-06T00:17:06-07: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 " Jun 06 00:17:06 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:17:06 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:17:07 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:07 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:08 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 06 00:17:08 volumio-2023 volumio[953]: info: Preload queue cleared Jun 06 00:17:09 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:17:09 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 585. Jun 06 00:17:09 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:17:09 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:17:09 volumio-2023 go-librespot[13250]: go-librespot daemon starting... Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=debug msg="app state loaded" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=debug msg="stored credentials not found" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=info msg="zeroconf server listening on port 43787" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=debug msg="obtained new client token: AAAJVpLULaXwZ/IpiwxaSuc36abjooETyaWUhV+BD67VJnVGKA7iD60ybj06LSaCQdW4zriSRQMZZ2e8JylhakrMbJ/YEKW0aQY3q6wtpRcmpkh3/ZxU1yCxVLgRL4B2Siugxi6IIi6LQds4hHnbskTVb3zN0+fbRt5Txz0i3qsGBd/aZtnD0P0kcZf0ZnRTdtKZoMIHNnHOnvm1gPiJ8T8OeiU71xVSH8xzzCHWnPDeT5G8fm7TqCW4lg==" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=debug msg="completed keyexchange" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07:00" level=debug msg="completed challenge" Jun 06 00:17:09 volumio-2023 go-librespot[13250]: time="2025-06-06T00:17:09-07: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 " Jun 06 00:17:09 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:17:09 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:17:10 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:10 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:12 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 06 00:17:12 volumio-2023 volumio[953]: info: Preload queue cleared Jun 06 00:17:13 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:13 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:13 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:17:13 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 586. Jun 06 00:17:13 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:17:13 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:17:13 volumio-2023 go-librespot[13259]: go-librespot daemon starting... Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=debug msg="app state loaded" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=debug msg="stored credentials not found" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=info msg="zeroconf server listening on port 35745" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=debug msg="obtained new client token: AAA462h2IaTG7wz2HW/9PvlBN7xktmdSx7Xf+0KGQ6o4o4zAYbGsq5/PjegyS7MISWGiZbfKSzV52LZUEThkVK9PBK3eTsurWqwYLbE273S+zg85ZWMZ7Kw0PFcfjKKyfbei0VX+hGnOVDTsWCBz+aKbz3VyOwfqJkfaFkDlfLAPDq0+97qSpZjy7Zih/dKFXVusoBdedY+rtQGFCj66/FOjluwwyefVViq6PM0ADUBwJRtvNXCRa3nC6Q==" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=debug msg="completed keyexchange" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07:00" level=debug msg="completed challenge" Jun 06 00:17:13 volumio-2023 go-librespot[13259]: time="2025-06-06T00:17:13-07: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 " Jun 06 00:17:13 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:17:13 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:17:15 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 06 00:17:15 volumio-2023 volumio[953]: info: Preload queue cleared Jun 06 00:17:16 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:16 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:16 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:17:16 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 587. Jun 06 00:17:16 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:17:16 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:17:16 volumio-2023 go-librespot[13267]: go-librespot daemon starting... Jun 06 00:17:16 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:16-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:17:16 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:16-07:00" level=debug msg="app state loaded" Jun 06 00:17:16 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:16-07:00" level=debug msg="stored credentials not found" Jun 06 00:17:16 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:16-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:17:17 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:17-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:17:17 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:17-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:17:17 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:17-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:17:17 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:17-07:00" level=info msg="zeroconf server listening on port 37207" Jun 06 00:17:17 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:17-07:00" level=debug msg="obtained new client token: AAAYk80ZlwANOPGwUmjExWX+R7dLgzA6OzBcGF3aEiempmMZltBI8Vk3OCl/lZe1dXzw9ctFIYzuzo3xXYBCZMxFlSPKVKQYmJgelRRxpzosX1jZ2Nv/ZY0Dg02LwTeZoUMhd2ECUfKScDZ9bQ8INMaGaxiImYpJl11OPURccg1sri8jc/o5sw/9rix2lYI63m0KL4o25IxzDK6J6x4PCfoIwHZuSlCaKl6siTnrGQaZsphyc2LF+ZezBg==" Jun 06 00:17:17 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:17-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:17:17 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:17-07:00" level=debug msg="completed keyexchange" Jun 06 00:17:17 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:17-07:00" level=debug msg="completed challenge" Jun 06 00:17:17 volumio-2023 go-librespot[13267]: time="2025-06-06T00:17:17-07: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 " Jun 06 00:17:17 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:17:17 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:17:18 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 06 00:17:19 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:19 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:19 volumio-2023 volumio[953]: error: Error browsingbb3513cb-b204-48e9-8624-7776f6ef9ff2:Error: Did not get expected response from server:{"Envelope":{"$":{"s:encodingStyle":"http://schemas.xmlsoap.org/soap/encoding/","xmlns:s":"http://schemas.xmlsoap.org/soap/envelope/"},"Body":[{"Fault":[{"faultcode":[{"_":"s:Client"}],"faultstring":[{"_":"UPnPError"}],"detail":[{"UPnPError":[{"$":{"xmlns":"urn:schemas-upnp-org:control-1-0"},"errorCode":[{"_":"501"}],"errorDescription":[{"_":"Action failed"}]}]}]}]}]}} Jun 06 00:17:19 volumio-2023 volumio[953]: error: Failed to execute browseSource: Jun 06 00:17:20 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:17:20 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 588. Jun 06 00:17:20 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:17:20 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:17:20 volumio-2023 go-librespot[13290]: go-librespot daemon starting... Jun 06 00:17:20 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:20-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:17:20 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:20-07:00" level=debug msg="app state loaded" Jun 06 00:17:20 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:20-07:00" level=debug msg="stored credentials not found" Jun 06 00:17:20 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:20-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:17:20 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:20-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:17:20 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:20-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:17:20 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:20-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:17:20 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:20-07:00" level=info msg="zeroconf server listening on port 33653" Jun 06 00:17:21 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:21-07:00" level=debug msg="obtained new client token: AAAeHZ3cIEFGZe1G4D5LQ50qTFmCqbldVBPsaZiTZ/OAnRFSZkfsmhBT55daYTR9DkHbq9+uVIxVICmfRRNFejWVi7uxFOKm6NB4a9jjtjlJ33HJxuOjoIPiPKiTZ83kFpqsb/etXWm39fUSwH/MBXSMHt8p4f9ULQv7eAdjm3a7WfCVOPMAf/bcvURXqx7uijSkG+mkng1pmltV0RnMg5MLSHSioMMlGVDVXs8KNNOZ3E9xYVsqrQY=" Jun 06 00:17:21 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:21-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:17:21 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:21-07:00" level=debug msg="completed keyexchange" Jun 06 00:17:21 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:21-07:00" level=debug msg="completed challenge" Jun 06 00:17:21 volumio-2023 go-librespot[13290]: time="2025-06-06T00:17:21-07: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 " Jun 06 00:17:21 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:17:21 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:17:21 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 06 00:17:21 volumio-2023 volumio[953]: info: Preload queue cleared Jun 06 00:17:22 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:22 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:23 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 06 00:17:23 volumio-2023 volumio[953]: info: Preload queue cleared Jun 06 00:17:24 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:17:24 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 589. Jun 06 00:17:24 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:17:24 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:17:24 volumio-2023 go-librespot[13300]: go-librespot daemon starting... Jun 06 00:17:24 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:24-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:17:24 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:24-07:00" level=debug msg="app state loaded" Jun 06 00:17:24 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:24-07:00" level=debug msg="stored credentials not found" Jun 06 00:17:24 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:24-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:17:24 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:24-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:17:24 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:24-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:17:24 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:24-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:17:24 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:24-07:00" level=info msg="zeroconf server listening on port 45611" Jun 06 00:17:24 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:24-07:00" level=debug msg="obtained new client token: AAANKZphotu+DtSJr8CADofYwvfKJRBRFBqh0mok8vIh7Mb/kW/n6mGyXmrMzB/VMQou/Z7D7BMllG8IQIYJ/QwWLlnrg8DQTzBputVxuTAl3Di8iKKnrw3SUuc6pAr+Lv/mDw3KxDrqh9VscOZLivMrJTUk3DbkcUjmXFFUaneQw+e0hu/Hlk+3c4wCkB2uaNkWG4tQeGFvTqBH1HwWkyMdHM4hy+DbLnCnpQJgrY+qzG1t/zNO/PdQVA==" Jun 06 00:17:24 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:24-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:17:25 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:25-07:00" level=debug msg="completed keyexchange" Jun 06 00:17:25 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:25-07:00" level=debug msg="completed challenge" Jun 06 00:17:25 volumio-2023 go-librespot[13300]: time="2025-06-06T00:17:25-07: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 " Jun 06 00:17:25 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:17:25 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:17:25 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:25 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:28 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:28 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:28 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:17:28 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 590. Jun 06 00:17:28 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:17:28 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:17:28 volumio-2023 go-librespot[13352]: go-librespot daemon starting... Jun 06 00:17:28 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:28-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:17:28 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:28-07:00" level=debug msg="app state loaded" Jun 06 00:17:28 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:28-07:00" level=debug msg="stored credentials not found" Jun 06 00:17:28 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:28-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:17:28 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:28-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:17:28 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:28-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:17:28 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:28-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:17:28 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:28-07:00" level=info msg="zeroconf server listening on port 46581" Jun 06 00:17:29 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:29-07:00" level=debug msg="obtained new client token: AADFkKYrMfbGOz93c5uN5ew2sSb0G9ZAvWXSODldj+KMoqFXOYvDCMY0H+tU32mHsGR+4kPd6KOKufhM+NjYXLU8QVQb7vCbNiebZW12y//Rw9sMc/EWtOwtcL3NJ55/62FrfSLQOfKdjo3oWqRVi9YUfYljyUIFqAbDHeWZ+PGVEk8ZTF7MjtV2hbRm/a2oxR6HQ7mh9bVYMdI9eJQgT4rOjfY1AotdsusnJWBlI/WU8vw/mRdbJu3EUw==" Jun 06 00:17:29 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:29-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:17:29 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:29-07:00" level=debug msg="completed keyexchange" Jun 06 00:17:29 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:29-07:00" level=debug msg="completed challenge" Jun 06 00:17:29 volumio-2023 go-librespot[13352]: time="2025-06-06T00:17:29-07: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 " Jun 06 00:17:29 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:17:29 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:17:29 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 06 00:17:29 volumio-2023 volumio[953]: info: Preload queue cleared Jun 06 00:17:31 volumio-2023 volumio[953]: info: Initializing connection to go-librespot Websocket Jun 06 00:17:31 volumio-2023 volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 06 00:17:32 volumio-2023 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 06 00:17:32 volumio-2023 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 591. Jun 06 00:17:32 volumio-2023 systemd[1]: Stopped go-librespot Daemon. Jun 06 00:17:32 volumio-2023 systemd[1]: Started go-librespot Daemon. Jun 06 00:17:32 volumio-2023 go-librespot[13376]: go-librespot daemon starting... Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=info msg="running go-librespot 0.2.0" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=debug msg="app state loaded" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=debug msg="stored credentials not found" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=info msg="zeroconf server listening on port 35827" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=debug msg="obtained new client token: AACesreGZV7rAIR6Im+f/r1euf56WhwcAsr9mcoM8If3XdXyj9hb3f7eV1Sg+FT9XBxzItLlaPaD6E1rVfBFK9daf7gJXHF9LR1Sd5XtEnZdu5yeWG9k2D2xL4umAgSwFhvYXCGcqCtysLRdg4wnRKNlOWPsL7zshL/3dCsIq9VKWQEdC2bP7Vv/vVHBZjAuVK55QWnb0xMdu9tgpmMVha9NBQFAxaxG2QzuWrKfiKvl1EfSwE/enrgBqQ==" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=debug msg="completed keyexchange" Jun 06 00:17:32 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:32-07:00" level=debug msg="completed challenge" Jun 06 00:17:33 volumio-2023 go-librespot[13376]: time="2025-06-06T00:17:33-07: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 " Jun 06 00:17:33 volumio-2023 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 06 00:17:33 volumio-2023 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 06 00:17:33 volumio-2023 volumio[953]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 06 00:17:33 volumio-2023 volumio[953]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 06 00:17:33 volumio-2023 volumio[953]: TypeError: Cannot read property 'length' of undefined Jun 06 00:17:33 volumio-2023 volumio[953]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Jun 06 00:17:33 volumio-2023 volumio[953]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Jun 06 00:17:33 volumio-2023 volumio[953]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Jun 06 00:17:33 volumio-2023 volumio[953]: at Parser.emit (events.js:315:20) Jun 06 00:17:33 volumio-2023 volumio[953]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Jun 06 00:17:33 volumio-2023 volumio[953]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Jun 06 00:17:33 volumio-2023 volumio[953]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Jun 06 00:17:33 volumio-2023 volumio[953]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Jun 06 00:17:33 volumio-2023 volumio[953]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Jun 06 00:17:33 volumio-2023 volumio[953]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Jun 06 00:17:33 volumio-2023 volumio[953]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Jun 06 00:17:33 volumio-2023 volumio[953]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Jun 06 00:17:33 volumio-2023 volumio[953]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Jun 06 00:17:33 volumio-2023 volumio[953]: at IncomingMessage.emit (events.js:327:22) Jun 06 00:17:33 volumio-2023 volumio[953]: at endReadableNT (internal/streams/readable.js:1327:12) Jun 06 00:17:33 volumio-2023 volumio[953]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jun 06 00:17:33 volumio-2023 volumio[953]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 06 00:17:34 volumio-2023 sudo[13393]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-06 00:16 Jun 06 00:17:34 volumio-2023 sudo[13393]: pam_unix(sudo:session): session opened for user root by (uid=0) 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"