-- Logs begin at Thu 2019-02-14 18:12:00 CST, end at Tue 2025-04-22 17:09:28 CST. -- Apr 22 17:08:00 volumio go-librespot[3472]: time="2025-04-22T17:08:00+08:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.241.202:4070: connect: connection refused" Apr 22 17:08:00 volumio volumio[850]: info: Connection to go-librespot Websocket closed Apr 22 17:08:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:01 volumio volumio[850]: info: Apr 22 17:08:01 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:01 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:01 volumio volumio[850]: info: Apr 22 17:08:01 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:01 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:01 volumio volumio[850]: info: ------------------------------ 2ms Apr 22 17:08:01 volumio volumio[850]: info: sendMpdCommand status took 1 milliseconds Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:01 volumio volumio[850]: info: Apr 22 17:08:01 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:01 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:01 volumio volumio[850]: info: Apr 22 17:08:01 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:01 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:01 volumio volumio[850]: info: Apr 22 17:08:01 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:01 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:01 volumio volumio[850]: info: Apr 22 17:08:01 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:01 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:01 volumio volumio[850]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 22 17:08:01 volumio volumio[850]: info: ------------------------------ 2ms Apr 22 17:08:01 volumio volumio[850]: info: sendMpdCommand status took 2 milliseconds Apr 22 17:08:01 volumio volumio[850]: info: ------------------------------ 1ms Apr 22 17:08:01 volumio volumio[850]: info: sendMpdCommand status took 2 milliseconds Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:01 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:01 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:01 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":23100,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ROCK ANTENNE - Rock Nonstop","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:01 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:01 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:01 volumio volumio[850]: info: ------------------------------ 44ms Apr 22 17:08:01 volumio volumio[850]: info: sendMpdCommand playlistinfo took 42 milliseconds Apr 22 17:08:01 volumio volumio[850]: info: sendMpdCommand playlistinfo took 43 milliseconds Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:01 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:01 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:01 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:01 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":23123,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ROCK ANTENNE - Rock Nonstop","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:01 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:01 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:01 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:01 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:01 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":23123,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ROCK ANTENNE - Rock Nonstop","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:01 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:01 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:01 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:01 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:01 volumio volumio[850]: info: ------------------------------ 124ms Apr 22 17:08:01 volumio volumio[850]: info: ------------------------------ 124ms Apr 22 17:08:01 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:01 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:01 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:01 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:01 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:01 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:02 volumio volumio[850]: info: Getting Spotify volume Apr 22 17:08:02 volumio volumio[850]: (node:850) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:02 volumio volumio[850]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 22 17:08:02 volumio volumio[850]: (node:850) 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: 38) Apr 22 17:08:02 volumio volumio[850]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 22 17:08:02 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Apr 22 17:08:02 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:03 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:03 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 39. Apr 22 17:08:03 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:03 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:03 volumio go-librespot[3496]: Librespot-go daemon starting... Apr 22 17:08:03 volumio go-librespot[3496]: time="2025-04-22T17:08:03+08:00" level=info msg="generated new device id: 4822ba3be9170e8a019414a15d0607059d9a4ea4" Apr 22 17:08:03 volumio go-librespot[3496]: time="2025-04-22T17:08:03+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:03 volumio volumio[850]: info: Apr 22 17:08:03 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:03 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:03 volumio volumio[850]: info: Apr 22 17:08:03 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:03 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:03 volumio volumio[850]: info: Apr 22 17:08:03 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:03 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:03 volumio volumio[850]: info: Apr 22 17:08:03 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:03 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:03 volumio volumio[850]: info: Apr 22 17:08:03 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:03 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:03 volumio volumio[850]: info: Apr 22 17:08:03 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:03 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:03 volumio volumio[850]: info: ------------------------------ 5ms Apr 22 17:08:03 volumio volumio[850]: info: sendMpdCommand status took 5 milliseconds Apr 22 17:08:03 volumio volumio[850]: info: ------------------------------ 6ms Apr 22 17:08:03 volumio volumio[850]: info: sendMpdCommand status took 6 milliseconds Apr 22 17:08:03 volumio volumio[850]: info: ------------------------------ 7ms Apr 22 17:08:03 volumio volumio[850]: info: sendMpdCommand status took 6 milliseconds Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:03 volumio volumio[850]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 22 17:08:03 volumio volumio[850]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 22 17:08:03 volumio volumio[850]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:03 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:03 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:03 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:03 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":23941,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ROCK ANTENNE - Rock Nonstop","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:03 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:03 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:03 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:03 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:03 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":23941,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ROCK ANTENNE - Rock Nonstop","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:03 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:03 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:03 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:03 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:03 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":23941,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ROCK ANTENNE - Rock Nonstop","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:03 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:03 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:03 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:03 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:03 volumio volumio[850]: info: ------------------------------ 116ms Apr 22 17:08:03 volumio volumio[850]: info: ------------------------------ 116ms Apr 22 17:08:03 volumio volumio[850]: info: ------------------------------ 116ms Apr 22 17:08:03 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:03 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:03 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:03 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:03 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:03 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:03 volumio go-librespot[3496]: time="2025-04-22T17:08:03+08:00" level=debug msg="obtained new client token: AAA1WEDsQ+XmbgZEnoQBMtRW0YVrb131z+jf4t1aUsVi2569XUwDDX5fTQ76dQYhf9p1hZVq9ZPQjQtZ6XpHOGW01MMQChyMPWo9w/XUjipPoKRlci+epDJyJ7naJKYas0g2E7ODTi5rULP8dKroW7YwhXM84z5oNDJjarhUeSsqnZd+gD/snj8nFIixFE6PxkVoCkk6MkGatRYxS/MvpheieATWiZ/A9yT+4dj7jvau3WKj/eyMIfeOImiiEftC" Apr 22 17:08:04 volumio go-librespot[3496]: time="2025-04-22T17:08:04+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:04 volumio go-librespot[3496]: time="2025-04-22T17:08:04+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:05 volumio go-librespot[3496]: time="2025-04-22T17:08:05+08:00" level=debug msg="completed challenge" Apr 22 17:08:05 volumio go-librespot[3496]: time="2025-04-22T17:08:05+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:05 volumio volumio[850]: info: Apr 22 17:08:05 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:05 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:05 volumio volumio[850]: info: Apr 22 17:08:05 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:05 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:05 volumio volumio[850]: info: Apr 22 17:08:05 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:05 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:05 volumio volumio[850]: info: Apr 22 17:08:05 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:05 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:05 volumio volumio[850]: info: Apr 22 17:08:05 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:05 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:05 volumio volumio[850]: info: Apr 22 17:08:05 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:05 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:05 volumio volumio[850]: info: ------------------------------ 8ms Apr 22 17:08:05 volumio volumio[850]: info: sendMpdCommand status took 7 milliseconds Apr 22 17:08:05 volumio volumio[850]: info: ------------------------------ 6ms Apr 22 17:08:05 volumio volumio[850]: info: sendMpdCommand status took 6 milliseconds Apr 22 17:08:05 volumio volumio[850]: info: ------------------------------ 6ms Apr 22 17:08:05 volumio volumio[850]: info: sendMpdCommand status took 5 milliseconds Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:05 volumio volumio[850]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 22 17:08:05 volumio volumio[850]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 22 17:08:05 volumio volumio[850]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:05 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:05 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:05 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:05 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":25092,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:05 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:05 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:05 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:05 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:05 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":25092,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:05 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:05 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:05 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:05 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:05 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":25092,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:05 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:05 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:05 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:05 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:05 volumio volumio[850]: info: ------------------------------ 134ms Apr 22 17:08:05 volumio volumio[850]: info: ------------------------------ 134ms Apr 22 17:08:05 volumio volumio[850]: info: ------------------------------ 134ms Apr 22 17:08:05 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:05 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:05 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:05 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:05 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:05 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:06 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:06 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 40. Apr 22 17:08:08 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:08 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:08 volumio go-librespot[3531]: Librespot-go daemon starting... Apr 22 17:08:08 volumio go-librespot[3531]: time="2025-04-22T17:08:08+08:00" level=info msg="generated new device id: 6fafe320d3661d15ab775c747394580a4a73c8d7" Apr 22 17:08:08 volumio go-librespot[3531]: time="2025-04-22T17:08:08+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:08 volumio go-librespot[3531]: time="2025-04-22T17:08:08+08:00" level=debug msg="obtained new client token: AABYknNSEfsLjzhRdw9wUPQ+nby8eiy3ZnGVng4kCnLTeEJyCksXmbrs/rI7UY2Hf4wEJrwIzTfCKkvxBZ6+AF67hPUObt4sU0GKO/PLD31fxeLnp9BrwyLdpv/rL/Is7bd3TfRyKCpq9LepJaL0jVMcOHA0jD6v3nVDREzB1BiQymk59gvRmHUl2M/5HGekByz3iGceaEwe0BfKWxT49rJlhjtaeHBJdWN+DiKyrFOoxJbCQOryshnmhOf7geNT" Apr 22 17:08:08 volumio go-librespot[3531]: time="2025-04-22T17:08:08+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:09 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:09 volumio go-librespot[3531]: time="2025-04-22T17:08:09+08:00" level=debug msg="new websocket client" Apr 22 17:08:09 volumio volumio[850]: info: Connection to go-librespot Websocket established Apr 22 17:08:09 volumio go-librespot[3531]: time="2025-04-22T17:08:09+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:09 volumio go-librespot[3531]: time="2025-04-22T17:08:09+08:00" level=debug msg="completed challenge" Apr 22 17:08:09 volumio go-librespot[3531]: time="2025-04-22T17:08:09+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:09 volumio volumio[850]: info: Connection to go-librespot Websocket closed Apr 22 17:08:12 volumio volumio[850]: info: Getting Spotify volume Apr 22 17:08:12 volumio volumio[850]: (node:850) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:12 volumio volumio[850]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 22 17:08:12 volumio volumio[850]: (node:850) 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: 39) Apr 22 17:08:12 volumio volumio[850]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 22 17:08:12 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Apr 22 17:08:12 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:12 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:12 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 41. Apr 22 17:08:13 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:13 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:13 volumio go-librespot[3552]: Librespot-go daemon starting... Apr 22 17:08:13 volumio go-librespot[3552]: time="2025-04-22T17:08:13+08:00" level=info msg="generated new device id: 515c7d1b3af19e6b27c1ae1fc09c5000c6a68659" Apr 22 17:08:13 volumio go-librespot[3552]: time="2025-04-22T17:08:13+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:13 volumio go-librespot[3552]: time="2025-04-22T17:08:13+08:00" level=debug msg="obtained new client token: AAC1lXniusJYra3hVUg/ojssttMr8FRzVnptQKGrV7go8BXr6Z7aSATpisMBwtZKwOCPXEiJ/C6SnHbdsKToAihBR0dqzIo3DF0s+bVIcTGfebO5xH3dJmHzRx2KpcNuJYu3+FG4gl3DcOZAzCmfKaxGhN0LsXT2TSSTWmbdUWtBAUPVtGDNnjt9Cy9S+xq2Eaqq0/JOlcKeoJC0V2X+tLMR72pH7SyfIuCkRBdTXPLt3E4ls82VC6XWoJ18y9pg" Apr 22 17:08:13 volumio go-librespot[3552]: time="2025-04-22T17:08:13+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:13 volumio go-librespot[3552]: time="2025-04-22T17:08:13+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:14 volumio go-librespot[3552]: time="2025-04-22T17:08:14+08:00" level=debug msg="completed challenge" Apr 22 17:08:14 volumio go-librespot[3552]: time="2025-04-22T17:08:14+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:14 volumio volumio[850]: info: Apr 22 17:08:14 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:14 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:14 volumio volumio[850]: info: Apr 22 17:08:14 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:14 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:14 volumio volumio[850]: info: Apr 22 17:08:14 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:14 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:14 volumio volumio[850]: info: Apr 22 17:08:14 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:14 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:14 volumio volumio[850]: info: Apr 22 17:08:14 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:14 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:14 volumio volumio[850]: info: Apr 22 17:08:14 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:14 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:14 volumio volumio[850]: info: ------------------------------ 4ms Apr 22 17:08:14 volumio volumio[850]: info: sendMpdCommand status took 3 milliseconds Apr 22 17:08:14 volumio volumio[850]: info: ------------------------------ 3ms Apr 22 17:08:14 volumio volumio[850]: info: sendMpdCommand status took 2 milliseconds Apr 22 17:08:14 volumio volumio[850]: info: ------------------------------ 3ms Apr 22 17:08:14 volumio volumio[850]: info: sendMpdCommand status took 2 milliseconds Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:14 volumio volumio[850]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 22 17:08:14 volumio volumio[850]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 22 17:08:14 volumio volumio[850]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:14 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:14 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:14 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:14 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:14 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":25970,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:14 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:14 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:14 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:14 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:14 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:14 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:14 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 17:08:14 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:15 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:15 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:15 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:15 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:15 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:15 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":25970,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:15 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:15 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:15 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:15 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:15 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:15 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:15 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:15 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:15 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:15 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:15 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:15 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:15 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":26050,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:15 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:15 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:15 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:15 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:15 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:15 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:15 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:15 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:15 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:15 volumio volumio[850]: info: ------------------------------ 97ms Apr 22 17:08:15 volumio volumio[850]: info: ------------------------------ 97ms Apr 22 17:08:15 volumio volumio[850]: info: ------------------------------ 97ms Apr 22 17:08:15 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:15 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:15 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:15 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:15 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:15 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:15 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:15 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 42. Apr 22 17:08:17 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:17 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:17 volumio go-librespot[3577]: Librespot-go daemon starting... Apr 22 17:08:17 volumio go-librespot[3577]: time="2025-04-22T17:08:17+08:00" level=info msg="generated new device id: 96ab31c794997dff8f06a520bcab542fb2c5224f" Apr 22 17:08:17 volumio go-librespot[3577]: time="2025-04-22T17:08:17+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:17 volumio go-librespot[3577]: time="2025-04-22T17:08:17+08:00" level=debug msg="obtained new client token: AADP+y/YCJwylqeisFYv7GAbXY4t/8HEL1BDeVl5P1WrNJIeMwNtkoJuApATZQ/Jzf1DUQ72axMyO/zfaP8RjGns6nuzbdQSJ7J1qtn8gsV9oGMK4cdPKKnx0VanRnGLYCbHLGLUFPUtIsesB9VRAlW3W1pw78mi6BpfnlJpeUQWxhSlPCFN6hZJkS8heDXrnEVx9Q3naSWNs6cKStkIxHtD41/u5e9WVXCnaI+7ASvl1aizBS00O5ie6yDaE4qx" Apr 22 17:08:18 volumio go-librespot[3577]: time="2025-04-22T17:08:18+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:18 volumio go-librespot[3577]: time="2025-04-22T17:08:18+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:18 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:18 volumio go-librespot[3577]: time="2025-04-22T17:08:18+08:00" level=debug msg="new websocket client" Apr 22 17:08:18 volumio volumio[850]: info: Connection to go-librespot Websocket established Apr 22 17:08:19 volumio go-librespot[3577]: time="2025-04-22T17:08:19+08:00" level=debug msg="completed challenge" Apr 22 17:08:19 volumio go-librespot[3577]: time="2025-04-22T17:08:19+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:19 volumio volumio[850]: info: Connection to go-librespot Websocket closed Apr 22 17:08:21 volumio volumio[850]: info: Getting Spotify volume Apr 22 17:08:21 volumio volumio[850]: (node:850) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:21 volumio volumio[850]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 22 17:08:21 volumio volumio[850]: (node:850) 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: 40) Apr 22 17:08:21 volumio volumio[850]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 22 17:08:22 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Apr 22 17:08:22 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:22 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:22 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:22 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 43. Apr 22 17:08:22 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:22 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:22 volumio go-librespot[3596]: Librespot-go daemon starting... Apr 22 17:08:22 volumio go-librespot[3596]: time="2025-04-22T17:08:22+08:00" level=info msg="generated new device id: 96a743899cdcffbac4054cebb7fce25c992917a4" Apr 22 17:08:22 volumio go-librespot[3596]: time="2025-04-22T17:08:22+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:22 volumio go-librespot[3596]: time="2025-04-22T17:08:22+08:00" level=debug msg="obtained new client token: AAB9uTWGa9wOkYZxJ/ihWpA2bF6Ri2mUrWZKrHZhMuuGncrY8Zvvac7OIjgQSDZ/BrZQm7ddHLpFxkDeC+J0+EmTDGaRG/QZvkLOLYhN0NMf9lJmmLI9/ViLr9HR0LJphXNO9KVOSJVouPeuxAoI0FsIWpCXxNhbj9p4Gf+I28G9fh73E/iIZ2aUmrht1CBoYO9SPOKMj88ygppQcmM015s2DqFtYfhp1XbNjgwGFhh19p/AQuKsucaRrhkd9Jq8" Apr 22 17:08:23 volumio go-librespot[3596]: time="2025-04-22T17:08:23+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:23 volumio go-librespot[3596]: time="2025-04-22T17:08:23+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:24 volumio go-librespot[3596]: time="2025-04-22T17:08:24+08:00" level=debug msg="completed challenge" Apr 22 17:08:24 volumio go-librespot[3596]: time="2025-04-22T17:08:24+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:25 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:25 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:26 volumio volumio[850]: info: Apr 22 17:08:26 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:26 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:26 volumio volumio[850]: info: Apr 22 17:08:26 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:26 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:26 volumio volumio[850]: info: Apr 22 17:08:26 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:26 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:26 volumio volumio[850]: info: Apr 22 17:08:26 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:26 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:26 volumio volumio[850]: info: Apr 22 17:08:26 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:26 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:26 volumio volumio[850]: info: Apr 22 17:08:26 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:26 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:26 volumio volumio[850]: info: ------------------------------ 8ms Apr 22 17:08:26 volumio volumio[850]: info: sendMpdCommand status took 7 milliseconds Apr 22 17:08:26 volumio volumio[850]: info: ------------------------------ 6ms Apr 22 17:08:26 volumio volumio[850]: info: sendMpdCommand status took 7 milliseconds Apr 22 17:08:26 volumio volumio[850]: info: ------------------------------ 6ms Apr 22 17:08:26 volumio volumio[850]: info: sendMpdCommand status took 3 milliseconds Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:26 volumio volumio[850]: info: sendMpdCommand playlistinfo took 6 milliseconds Apr 22 17:08:26 volumio volumio[850]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 22 17:08:26 volumio volumio[850]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:26 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:26 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:26 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:26 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":26868,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:26 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:26 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:26 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:26 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:26 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":26994,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:26 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:26 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:26 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:26 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:26 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":27051,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:26 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:26 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:26 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:26 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:26 volumio volumio[850]: info: ------------------------------ 89ms Apr 22 17:08:26 volumio volumio[850]: info: ------------------------------ 89ms Apr 22 17:08:26 volumio volumio[850]: info: ------------------------------ 88ms Apr 22 17:08:26 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:26 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:26 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:26 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:26 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 44. Apr 22 17:08:27 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:27 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:27 volumio go-librespot[3623]: Librespot-go daemon starting... Apr 22 17:08:27 volumio go-librespot[3623]: time="2025-04-22T17:08:27+08:00" level=info msg="generated new device id: 41075563a586a5f92ad7699786372dc0b1358573" Apr 22 17:08:27 volumio go-librespot[3623]: time="2025-04-22T17:08:27+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:27 volumio go-librespot[3623]: time="2025-04-22T17:08:27+08:00" level=debug msg="obtained new client token: AAC8rTGLJGSCIWl0K7IRGcbivCZgAZM/I3s+EkyHSPhQRp8qZKrfpI3tSqZz9Hd2/Qx/JVsmiq52zwpVGvbE3ULF/gfIsci/dmvQXPjFDA3sZEsWCAR9q8kGbWcRBKz9FZ5uJEixDWC4mAQvfij2CfmUb2zdr3RV/YqPlNGEI9qiE0jaWO0cjHtbQWdZSQH2PKkL/G2rw0chlrSfLkutGr5a0CTAylHvcvQt5Th9MEYVPtY2LQ/2UmatYHWwzCVA" Apr 22 17:08:28 volumio go-librespot[3623]: time="2025-04-22T17:08:28+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:28 volumio go-librespot[3623]: time="2025-04-22T17:08:28+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:28 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:28 volumio volumio[850]: info: Connection to go-librespot Websocket established Apr 22 17:08:28 volumio go-librespot[3623]: time="2025-04-22T17:08:28+08:00" level=debug msg="new websocket client" Apr 22 17:08:28 volumio volumio[850]: info: Apr 22 17:08:28 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:28 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:28 volumio volumio[850]: info: Apr 22 17:08:28 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:28 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:28 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:28 volumio volumio[850]: info: Apr 22 17:08:28 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:28 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:28 volumio volumio[850]: info: Apr 22 17:08:28 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:28 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:28 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:28 volumio volumio[850]: info: Apr 22 17:08:28 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:28 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:28 volumio volumio[850]: info: Apr 22 17:08:28 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:28 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:28 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:28 volumio volumio[850]: info: ------------------------------ 5ms Apr 22 17:08:28 volumio volumio[850]: info: sendMpdCommand status took 4 milliseconds Apr 22 17:08:28 volumio volumio[850]: info: ------------------------------ 5ms Apr 22 17:08:28 volumio volumio[850]: info: sendMpdCommand status took 3 milliseconds Apr 22 17:08:28 volumio volumio[850]: info: ------------------------------ 3ms Apr 22 17:08:28 volumio volumio[850]: info: sendMpdCommand status took 2 milliseconds Apr 22 17:08:28 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:28 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:28 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:28 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:28 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:28 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:28 volumio volumio[850]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 22 17:08:28 volumio volumio[850]: info: sendMpdCommand playlistinfo took 6 milliseconds Apr 22 17:08:28 volumio volumio[850]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 22 17:08:28 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:28 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:28 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:28 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":27929,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:28 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:28 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:28 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:28 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:28 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":27929,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:28 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:28 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:28 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:28 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:28 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":27929,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:28 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:28 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:28 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:28 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:28 volumio volumio[850]: info: ------------------------------ 106ms Apr 22 17:08:28 volumio volumio[850]: info: ------------------------------ 106ms Apr 22 17:08:28 volumio volumio[850]: info: ------------------------------ 104ms Apr 22 17:08:28 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:28 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:28 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:28 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:28 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:28 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:28 volumio go-librespot[3623]: time="2025-04-22T17:08:28+08:00" level=debug msg="completed challenge" Apr 22 17:08:28 volumio go-librespot[3623]: time="2025-04-22T17:08:28+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:28 volumio volumio[850]: info: Connection to go-librespot Websocket closed Apr 22 17:08:29 volumio volumio[850]: info: Apr 22 17:08:29 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:29 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:29 volumio volumio[850]: info: Apr 22 17:08:29 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:29 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:29 volumio volumio[850]: info: Apr 22 17:08:29 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:29 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:29 volumio volumio[850]: info: Apr 22 17:08:29 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:29 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:29 volumio volumio[850]: info: Apr 22 17:08:29 volumio volumio[850]: ---------------------------- MPD announces system playlist update Apr 22 17:08:29 volumio volumio[850]: info: Ignoring MPD Status Update Apr 22 17:08:29 volumio volumio[850]: info: Apr 22 17:08:29 volumio volumio[850]: ---------------------------- MPD announces state update: player Apr 22 17:08:29 volumio volumio[850]: info: ControllerMpd::getState Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Apr 22 17:08:29 volumio volumio[850]: info: ------------------------------ 11ms Apr 22 17:08:29 volumio volumio[850]: info: sendMpdCommand status took 10 milliseconds Apr 22 17:08:29 volumio volumio[850]: info: ------------------------------ 8ms Apr 22 17:08:29 volumio volumio[850]: info: sendMpdCommand status took 4 milliseconds Apr 22 17:08:29 volumio volumio[850]: info: ------------------------------ 4ms Apr 22 17:08:29 volumio volumio[850]: info: sendMpdCommand status took 2 milliseconds Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::parseState Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 22 17:08:29 volumio volumio[850]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 22 17:08:29 volumio volumio[850]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 22 17:08:29 volumio volumio[850]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:29 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Apr 22 17:08:29 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:29 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:29 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":29035,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:29 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:29 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:29 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:29 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:29 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":29080,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:29 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:29 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:29 volumio volumio[850]: info: ControllerMpd::pushState Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::servicePushState Apr 22 17:08:29 volumio volumio[850]: info: CorePlayQueue::getTrack 0 Apr 22 17:08:29 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":29080,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Die Toten Hosen - Laune der Natur","artist":"ROCK ANTENNE","album":null,"uri":"http://stream.antenne.de:80/rockantenne","trackType":""} Apr 22 17:08:29 volumio volumio[850]: verbose: CURRENT POSITION 0 Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Apr 22 17:08:29 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:29 volumio volumio[850]: info: CoreStateMachine::pushState Apr 22 17:08:29 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Apr 22 17:08:29 volumio volumio[850]: info: ------------------------------ 110ms Apr 22 17:08:29 volumio volumio[850]: info: ------------------------------ 108ms Apr 22 17:08:29 volumio volumio[850]: info: ------------------------------ 103ms Apr 22 17:08:29 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:29 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:29 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:29 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:29 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:29 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:31 volumio volumio[850]: info: Getting Spotify volume Apr 22 17:08:31 volumio volumio[850]: (node:850) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:31 volumio volumio[850]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 22 17:08:31 volumio volumio[850]: (node:850) 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: 41) Apr 22 17:08:31 volumio volumio[850]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 22 17:08:31 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Apr 22 17:08:31 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:31 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:31 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 45. Apr 22 17:08:32 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:32 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:32 volumio go-librespot[3655]: Librespot-go daemon starting... Apr 22 17:08:32 volumio go-librespot[3655]: time="2025-04-22T17:08:32+08:00" level=info msg="generated new device id: 100e0cdc479d3e03091dba559a8c3ddc0fab08a1" Apr 22 17:08:32 volumio go-librespot[3655]: time="2025-04-22T17:08:32+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:32 volumio go-librespot[3655]: time="2025-04-22T17:08:32+08:00" level=debug msg="obtained new client token: AABeQO5wSbHc44SpxXEhYrnKi/SX3BQRqdpg2ufeuYq+tg/WF9Msfl1gJOQUaPGx0jgAiQETDwwOzaDaoqZKM/a0WDV6/WRgC/fJA5gwkV7Xz9eCOtDTgEVXcUrQnaqYguyo8MmRZGhXrmnBvySTkVfGMu9swIeSeCqPbqanfQHG7kBJdcprGKRl0OdskndQ5qZSYmMIUNJW8Zxy0uzxDWsXQR+VQLSWTIOLOC+aZrL1n3h8dBJtLTGSabRrdo7H" Apr 22 17:08:32 volumio go-librespot[3655]: time="2025-04-22T17:08:32+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:33 volumio go-librespot[3655]: time="2025-04-22T17:08:33+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:33 volumio go-librespot[3655]: time="2025-04-22T17:08:33+08:00" level=debug msg="completed challenge" Apr 22 17:08:33 volumio go-librespot[3655]: time="2025-04-22T17:08:33+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:34 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:34 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 46. Apr 22 17:08:36 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:36 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:36 volumio go-librespot[3673]: Librespot-go daemon starting... Apr 22 17:08:36 volumio go-librespot[3673]: time="2025-04-22T17:08:36+08:00" level=info msg="generated new device id: 6163b3c3644ad08f190527b65279b84dfc0f9996" Apr 22 17:08:36 volumio go-librespot[3673]: time="2025-04-22T17:08:36+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:37 volumio go-librespot[3673]: time="2025-04-22T17:08:37+08:00" level=debug msg="obtained new client token: AABmujH3NminzHeyAPNuzVJ08qJFMR0gRfqJ1S5HP1Jvquj4AVxbv7d71CFG0gbFrv5sAv8NU+SDuNs5T+gGQ4yNTENBEmu8KEa6QBKyGN0sYipKUO8X1wzW81FV7p39IJmP3FCFtG++JIegbtM4sTkdv32Lg3gy84PfptybPGesqoUXN2Tq+3DiYxWyGhrSJ9l70lOtgt5JIcX2OZi1WCTbzxqSnAdozmJDP33jgEzey8jht3neu9TlmzClEg==" Apr 22 17:08:37 volumio go-librespot[3673]: time="2025-04-22T17:08:37+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:37 volumio go-librespot[3673]: time="2025-04-22T17:08:37+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:37 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:37 volumio go-librespot[3673]: time="2025-04-22T17:08:37+08:00" level=debug msg="new websocket client" Apr 22 17:08:37 volumio volumio[850]: info: Connection to go-librespot Websocket established Apr 22 17:08:38 volumio go-librespot[3673]: time="2025-04-22T17:08:38+08:00" level=debug msg="completed challenge" Apr 22 17:08:38 volumio go-librespot[3673]: time="2025-04-22T17:08:38+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:38 volumio volumio[850]: info: Connection to go-librespot Websocket closed Apr 22 17:08:40 volumio volumio[850]: info: Getting Spotify volume Apr 22 17:08:40 volumio volumio[850]: (node:850) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:40 volumio volumio[850]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 22 17:08:40 volumio volumio[850]: (node:850) 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: 42) Apr 22 17:08:40 volumio volumio[850]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 22 17:08:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Apr 22 17:08:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:41 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:41 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:41 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 47. Apr 22 17:08:41 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:41 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:41 volumio go-librespot[3689]: Librespot-go daemon starting... Apr 22 17:08:41 volumio go-librespot[3689]: time="2025-04-22T17:08:41+08:00" level=info msg="generated new device id: 1617a0038ce6aa36a77b9bad8b56f96b4bcec4ad" Apr 22 17:08:41 volumio go-librespot[3689]: time="2025-04-22T17:08:41+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:41 volumio go-librespot[3689]: time="2025-04-22T17:08:41+08:00" level=debug msg="obtained new client token: AAC8VRjV3s7hBqvO1t4jWmZms0vCaH91xzqnGpw7CcmDWN6ohp57SII4PesOr5u23TniO+VRFW6W98tTGLe49F3WdR9vs/NqcqXbz+PSKvcMcTk5+XL/5oX2nfvsyUg+siPWz5TAfYgqbmcL92PEUeO8WBdawZKEFBruzXQYdjB9A3lWum/tq/jaiC4zmPhnsIKUdmyAy9OJGZUAdLxlYswfP4B/I93vuCXikTdmH1XLdK38W5zL7DIOAHwHjklm" Apr 22 17:08:41 volumio go-librespot[3689]: time="2025-04-22T17:08:41+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:42 volumio go-librespot[3689]: time="2025-04-22T17:08:42+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:43 volumio go-librespot[3689]: time="2025-04-22T17:08:43+08:00" level=debug msg="completed challenge" Apr 22 17:08:43 volumio go-librespot[3689]: time="2025-04-22T17:08:43+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:44 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:44 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:46 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 48. Apr 22 17:08:46 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:46 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:46 volumio go-librespot[3708]: Librespot-go daemon starting... Apr 22 17:08:46 volumio go-librespot[3708]: time="2025-04-22T17:08:46+08:00" level=info msg="generated new device id: bf9d8c4419b24c983742b476743227b3f940a0f5" Apr 22 17:08:46 volumio go-librespot[3708]: time="2025-04-22T17:08:46+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:46 volumio go-librespot[3708]: time="2025-04-22T17:08:46+08:00" level=debug msg="obtained new client token: AABiPgNldNyAjOvJ/D8e/7ftdCWHF42fk+QW85C4jZ2JgZ7ISoGKy4vUH0589xO0atfXQfjZecTWlYJUwRGb1Z3+kwMGnq+dUuuRS6MffRraANSAAIulEeK+80PAYOB67//FJqkcAodI8DcwgTg3Har+fuG8HeQYfJhQ+zpyurInJ3Y9CZBThXbxqCAVWr3oEN+/VhOjU2fiALwUXexBMuR0LUUMQ9pdgl3T0s77Wuaeqjd/o0LshuY7AalrNdS1" Apr 22 17:08:46 volumio go-librespot[3708]: time="2025-04-22T17:08:46+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:47 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:47 volumio go-librespot[3708]: time="2025-04-22T17:08:47+08:00" level=debug msg="new websocket client" Apr 22 17:08:47 volumio volumio[850]: info: Connection to go-librespot Websocket established Apr 22 17:08:47 volumio go-librespot[3708]: time="2025-04-22T17:08:47+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:47 volumio go-librespot[3708]: time="2025-04-22T17:08:47+08:00" level=debug msg="completed challenge" Apr 22 17:08:48 volumio go-librespot[3708]: time="2025-04-22T17:08:48+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:48 volumio volumio[850]: info: Connection to go-librespot Websocket closed Apr 22 17:08:50 volumio volumio[850]: info: Getting Spotify volume Apr 22 17:08:50 volumio volumio[850]: (node:850) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:50 volumio volumio[850]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 22 17:08:50 volumio volumio[850]: (node:850) 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: 43) Apr 22 17:08:50 volumio volumio[850]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 22 17:08:50 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Apr 22 17:08:50 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:08:51 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:51 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 49. Apr 22 17:08:51 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:51 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:51 volumio go-librespot[3726]: Librespot-go daemon starting... Apr 22 17:08:51 volumio go-librespot[3726]: time="2025-04-22T17:08:51+08:00" level=info msg="generated new device id: 107b3d85b83d7e30df480e78386371e404c743f0" Apr 22 17:08:51 volumio go-librespot[3726]: time="2025-04-22T17:08:51+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:51 volumio go-librespot[3726]: time="2025-04-22T17:08:51+08:00" level=debug msg="obtained new client token: AAALBEPYBrXmT9YNc2QkaPHZ8l5aWP7LZNPeaWVafWea+cB0YMUcw4V4vDuY3fSM6r8QzIarUaklK+54OPDDY2E4jayI+bZ9lvXKFGi8Hps8vijXZIKfgwxJ7zFDbrqYpjfbQulB4iEwipkEduDiDMvDtJPFmSZy9bOk3WQmnIy3wjpEW7yLVqZbQJbmQCopCx/eV/EezHKX2wtV8cErKkwgevswgWUGiBghxpcgBSpenYtBfrQUdZUVRH4SaXyr" Apr 22 17:08:51 volumio go-librespot[3726]: time="2025-04-22T17:08:51+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:52 volumio go-librespot[3726]: time="2025-04-22T17:08:52+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:52 volumio go-librespot[3726]: time="2025-04-22T17:08:52+08:00" level=debug msg="completed challenge" Apr 22 17:08:52 volumio go-librespot[3726]: time="2025-04-22T17:08:52+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:54 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:54 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:08:55 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:08:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 50. Apr 22 17:08:55 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:08:55 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:08:55 volumio go-librespot[3743]: Librespot-go daemon starting... Apr 22 17:08:55 volumio go-librespot[3743]: time="2025-04-22T17:08:55+08:00" level=info msg="generated new device id: 2927236040d58f1310a82147466d138e6bc06071" Apr 22 17:08:55 volumio go-librespot[3743]: time="2025-04-22T17:08:55+08:00" level=debug msg="stored credentials not found" Apr 22 17:08:55 volumio go-librespot[3743]: time="2025-04-22T17:08:55+08:00" level=debug msg="obtained new client token: AADf88iOKs68Nh9j+2nIZfThtucRRCSyt+pYDABCCM+E5jWNEt8EciJuJidAakYd8UrdFBO9jE38Uu5VEZm1nSkj/Ockc839qYfBoVpZM1HlpYGCXHyJLwCSFS9sSmbljluZIwRHjqplZj/+WvuMGE/gzrhZPyJgSLgQk91APHepfuZXisRPWxyobQZb9Ba0gg1LLdQml/iphRpO5Td58gaHIc9iL8yyKsqjT8KBL8o49W84xjt3oLkjoofT+xl4" Apr 22 17:08:56 volumio go-librespot[3743]: time="2025-04-22T17:08:56+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:08:56 volumio go-librespot[3743]: time="2025-04-22T17:08:56+08:00" level=debug msg="completed keyexchange" Apr 22 17:08:56 volumio go-librespot[3743]: time="2025-04-22T17:08:56+08:00" level=debug msg="completed challenge" Apr 22 17:08:56 volumio go-librespot[3743]: time="2025-04-22T17:08:56+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:08:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:08:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:08:57 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:08:57 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:09:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 51. Apr 22 17:09:00 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:09:00 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:09:00 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:00 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:09:00 volumio go-librespot[3802]: Librespot-go daemon starting... Apr 22 17:09:00 volumio go-librespot[3802]: time="2025-04-22T17:09:00+08:00" level=info msg="generated new device id: a198eddd6f9e5adee92fe316411f471c8f6b38f5" Apr 22 17:09:00 volumio go-librespot[3802]: time="2025-04-22T17:09:00+08:00" level=debug msg="stored credentials not found" Apr 22 17:09:00 volumio go-librespot[3802]: time="2025-04-22T17:09:00+08:00" level=debug msg="obtained new client token: AAAB5lLuXWUeU5QWIa9eiaEMFxgJPd18QFz/B5bsUlvCCO+yhIRs7+pRwjJ2kJ88IazWhwReWijTFzCo1PCFzX09Z5gmLKnemIS3TOFGXpbXPO8MivAXSAALyL7xPcPG4m32wIhR+QHWWjstVSgq4C8m3ed4yN0JaYbP1tP0B1VOCY13uJberZXdH/y0aGWsGW3RsodlnZ5yBLzIiYtEpHObm4jBZva0dBLk4wGgQJouGIH80TL3s6shawrw5tJ3" Apr 22 17:09:00 volumio go-librespot[3802]: time="2025-04-22T17:09:00+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 22 17:09:00 volumio go-librespot[3802]: time="2025-04-22T17:09:00+08:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.241.202:4070: connect: connection refused" Apr 22 17:09:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:09:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:09:03 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:09:03 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:09:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 52. Apr 22 17:09:03 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:09:03 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:09:03 volumio go-librespot[3817]: Librespot-go daemon starting... Apr 22 17:09:03 volumio go-librespot[3817]: time="2025-04-22T17:09:03+08:00" level=info msg="generated new device id: 2fe0e29e3bbc8cbe1b03a6b8ad504e03856bb25a" Apr 22 17:09:03 volumio go-librespot[3817]: time="2025-04-22T17:09:03+08:00" level=debug msg="stored credentials not found" Apr 22 17:09:04 volumio go-librespot[3817]: time="2025-04-22T17:09:04+08:00" level=debug msg="obtained new client token: AACFn8v4vanblhoepd4Ed5X8frsxRnFXzHhmmPmlMyCrLqMYt5lJo9aI/Fu6BeXRimWAWi9m2980OA2k+nFDKo9dhzVXIhDoLgYv06cZrDZEK7xnab1zp2IcQM/8+3LZ66NSVGkqw4KYf31Ef2gRNGV3TxIRTyl0so96LL6NUXXoMygnYtaNuEUMB4NQ+tnjnbquajSXNOi1eVKFgh/QWMRGwWXq3mcl9IEYgT7dDJulZTS94fiJowJwHGAXKw==" Apr 22 17:09:04 volumio go-librespot[3817]: time="2025-04-22T17:09:04+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 22 17:09:04 volumio go-librespot[3817]: time="2025-04-22T17:09:04+08:00" level=debug msg="completed keyexchange" Apr 22 17:09:05 volumio go-librespot[3817]: time="2025-04-22T17:09:05+08:00" level=debug msg="completed challenge" Apr 22 17:09:05 volumio go-librespot[3817]: time="2025-04-22T17:09:05+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:09:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:09:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:09:06 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:09:06 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:09:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 53. Apr 22 17:09:08 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:09:08 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:09:08 volumio go-librespot[3835]: Librespot-go daemon starting... Apr 22 17:09:08 volumio go-librespot[3835]: time="2025-04-22T17:09:08+08:00" level=info msg="generated new device id: db18a2ceb57b58721e5598ebfdd10e70db49f022" Apr 22 17:09:08 volumio go-librespot[3835]: time="2025-04-22T17:09:08+08:00" level=debug msg="stored credentials not found" Apr 22 17:09:08 volumio go-librespot[3835]: time="2025-04-22T17:09:08+08:00" level=debug msg="obtained new client token: AABwcDyS+yySGZNhpRCgFMVjzc3mraG1eBGEoSPPluTRhDhQOZ+S8GGdUmG2JwlQN/D+Gf75iChgnbPJDFxM1LWV/NQjHFV1p0A8rHycaKv+9qm/jGY48Ejh4cjvu7omegUrU6OLscx+yMaKYJY3iYdkNFJuEpu/3wMqbPT0CqHTvVg6DbaosCbmMyJcEN/Ldol84hjBH7gHWxpFbRX2nMLBQNM9YtBTvv2LH5HaSb7unXFAOQbwBx/e6cOLYFsX" Apr 22 17:09:08 volumio go-librespot[3835]: time="2025-04-22T17:09:08+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:09:09 volumio go-librespot[3835]: time="2025-04-22T17:09:09+08:00" level=debug msg="completed keyexchange" Apr 22 17:09:09 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:09:09 volumio go-librespot[3835]: time="2025-04-22T17:09:09+08:00" level=debug msg="new websocket client" Apr 22 17:09:09 volumio volumio[850]: info: Connection to go-librespot Websocket established Apr 22 17:09:09 volumio go-librespot[3835]: time="2025-04-22T17:09:09+08:00" level=debug msg="completed challenge" Apr 22 17:09:09 volumio go-librespot[3835]: time="2025-04-22T17:09:09+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:09:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:09:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:09:09 volumio volumio[850]: info: Connection to go-librespot Websocket closed Apr 22 17:09:12 volumio volumio[850]: info: Getting Spotify volume Apr 22 17:09:12 volumio volumio[850]: (node:850) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:12 volumio volumio[850]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 22 17:09:12 volumio volumio[850]: (node:850) 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: 44) Apr 22 17:09:12 volumio volumio[850]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 22 17:09:12 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Apr 22 17:09:12 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Apr 22 17:09:12 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:09:12 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:12 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:09:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 54. Apr 22 17:09:12 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:09:12 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:09:12 volumio go-librespot[3853]: Librespot-go daemon starting... Apr 22 17:09:12 volumio go-librespot[3853]: time="2025-04-22T17:09:12+08:00" level=info msg="generated new device id: fe6f45c279671805465116aa9df6907ec1561717" Apr 22 17:09:12 volumio go-librespot[3853]: time="2025-04-22T17:09:12+08:00" level=debug msg="stored credentials not found" Apr 22 17:09:13 volumio go-librespot[3853]: time="2025-04-22T17:09:13+08:00" level=debug msg="obtained new client token: AAAeeIcBrvMVz/4j18V+0JUeTZSjql/82SMUBTu1VzgaBMymOscsAC//lp3b95meUhPIJE2YH23BWXEMMsNAd9fUlP9PSnTXeubafsvxspt+npfpbIaz76wZOqkt3QOAeBnPC0e8v9NK5QXP9ZZ/rAB9vVxS22p6sn+T477IKKkyuj54RijBCbPUVWKYVONjQd2ouen2+Nx/ML0+JH/QkvbyNw/LD7QtNmtkG0R2rXL2bvSlf+Micn8AfS2XIQ==" Apr 22 17:09:13 volumio go-librespot[3853]: time="2025-04-22T17:09:13+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:09:13 volumio go-librespot[3853]: time="2025-04-22T17:09:13+08:00" level=debug msg="completed keyexchange" Apr 22 17:09:14 volumio go-librespot[3853]: time="2025-04-22T17:09:14+08:00" level=debug msg="completed challenge" Apr 22 17:09:14 volumio go-librespot[3853]: time="2025-04-22T17:09:14+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:09:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:09:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:09:15 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:09:15 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:09:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 55. Apr 22 17:09:17 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:09:17 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:09:17 volumio go-librespot[3871]: Librespot-go daemon starting... Apr 22 17:09:17 volumio go-librespot[3871]: time="2025-04-22T17:09:17+08:00" level=info msg="generated new device id: 8ff0367404970d96adfd446d53fec06931eaef7f" Apr 22 17:09:17 volumio go-librespot[3871]: time="2025-04-22T17:09:17+08:00" level=debug msg="stored credentials not found" Apr 22 17:09:17 volumio go-librespot[3871]: time="2025-04-22T17:09:17+08:00" level=debug msg="obtained new client token: AAAYvFrL0Ekwd35zHpFLNNgsV21IaTm8UEpysH2X8lcMSLgSIQ25EaDuEFk35KTrvWtqVwG1QvETJPdezlcdMlTJEdWHBsdzHvZ//OLezjO7jZ4LPLMeRSASeh2AN/qlUjSXFcQBQxbBOiNxRiZ1i63KewJZtu7QLqjOmEVtwbuBolAhlWf7kPA6x4ThENxJygQuGiBA1j2gYO8VfNkerzbVQ3P4oFHaPjGSVesLPvWjCE6bztRBgrOLszQ4xRvu" Apr 22 17:09:17 volumio go-librespot[3871]: time="2025-04-22T17:09:17+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:09:18 volumio go-librespot[3871]: time="2025-04-22T17:09:18+08:00" level=debug msg="completed keyexchange" Apr 22 17:09:18 volumio go-librespot[3871]: time="2025-04-22T17:09:18+08:00" level=debug msg="completed challenge" Apr 22 17:09:18 volumio go-librespot[3871]: time="2025-04-22T17:09:18+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:09:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:09:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:09:18 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:09:18 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:21 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:09:21 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:21 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:09:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56. Apr 22 17:09:21 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:09:21 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:09:21 volumio go-librespot[3889]: Librespot-go daemon starting... Apr 22 17:09:21 volumio go-librespot[3889]: time="2025-04-22T17:09:21+08:00" level=info msg="generated new device id: a299639a474b7002d47c7cb016ea2ca5c1c371b8" Apr 22 17:09:21 volumio go-librespot[3889]: time="2025-04-22T17:09:21+08:00" level=debug msg="stored credentials not found" Apr 22 17:09:22 volumio go-librespot[3889]: time="2025-04-22T17:09:22+08:00" level=debug msg="obtained new client token: AAA9AAgMkaIjhCiQpI8y6ipy9SSDj6EdveePgfXnXavZRZSqJknXsP6LLXLXayvY3cz11S+XPAs/zdWfPDnyD4EWHbmC/z5thQ9ulgLuVioMJhmxzmz0y3jgF5fgsiMn9EAw0VfDGyGPe9tq6ReRzJCc5TKvo9lS+XPexqN46akxAhPJUHUVqYklnX/Erd3eGiu+6pTjFH+ZX4BnLwlv9asDQHHH6fUw0mq6Aa8u2UoYvU5PqpbNGqi3zTaaEA==" Apr 22 17:09:22 volumio go-librespot[3889]: time="2025-04-22T17:09:22+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:09:22 volumio go-librespot[3889]: time="2025-04-22T17:09:22+08:00" level=debug msg="completed keyexchange" Apr 22 17:09:23 volumio go-librespot[3889]: time="2025-04-22T17:09:23+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed solving challenge: failed login: BadCredentials" Apr 22 17:09:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:09:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:09:24 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:09:24 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 22 17:09:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57. Apr 22 17:09:26 volumio systemd[1]: Stopped go-librespot Daemon. Apr 22 17:09:26 volumio systemd[1]: Started go-librespot Daemon. Apr 22 17:09:26 volumio go-librespot[3909]: Librespot-go daemon starting... Apr 22 17:09:26 volumio go-librespot[3909]: time="2025-04-22T17:09:26+08:00" level=info msg="generated new device id: e6c65425061fdc6cacba6c7eb715eac5023b6fdb" Apr 22 17:09:26 volumio go-librespot[3909]: time="2025-04-22T17:09:26+08:00" level=debug msg="stored credentials not found" Apr 22 17:09:26 volumio go-librespot[3909]: time="2025-04-22T17:09:26+08:00" level=debug msg="obtained new client token: AABzZ9hSsJJDTR3gkIsXkrgqnmt8hrNiGew3sBgd1usAVfuDlCi5h+gvLx0DlT9UWX3VDskppdI1kps3wict98584aaWOPB/hfXLHmAoppeIl+tWatQFIZ0UexmeWy6PC6yXX0pI+oaoBHt1NXIeneMjeEqwCLdBq0Xl5iWLiWE6KJtLT5BLzzZ1YJ7gt+HDueDFcEjyvzkp+XUjT/vPJxjsTG6T2qQ/q46/D1WM5M8onRnyAwuxSS/6o6SMiUKz" Apr 22 17:09:26 volumio go-librespot[3909]: time="2025-04-22T17:09:26+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 17:09:27 volumio go-librespot[3909]: time="2025-04-22T17:09:27+08:00" level=debug msg="completed keyexchange" Apr 22 17:09:27 volumio go-librespot[3909]: time="2025-04-22T17:09:27+08:00" level=debug msg="completed challenge" Apr 22 17:09:27 volumio go-librespot[3909]: time="2025-04-22T17:09:27+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 22 17:09:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 22 17:09:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 22 17:09:27 volumio volumio[850]: info: Initializing connection to go-librespot Websocket Apr 22 17:09:27 volumio volumio[850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 22 17:09:28 volumio volumio[850]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 22 17:09:28 volumio volumio[850]: Error: connect ETIMEDOUT 69.63.176.143:80 Apr 22 17:09:28 volumio volumio[850]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Apr 22 17:09:28 volumio volumio[850]: errno: -110, Apr 22 17:09:28 volumio volumio[850]: code: 'ETIMEDOUT', Apr 22 17:09:28 volumio volumio[850]: syscall: 'connect', Apr 22 17:09:28 volumio volumio[850]: address: '69.63.176.143', Apr 22 17:09:28 volumio volumio[850]: port: 80 Apr 22 17:09:28 volumio volumio[850]: } Apr 22 17:09:28 volumio volumio[850]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 22 17:09:28 volumio sudo[3930]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-22 17:08 Apr 22 17:09:28 volumio sudo[3930]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"