-- Logs begin at Sun 2024-04-14 14:23:07 CST, end at Sun 2024-04-14 14:34:27 CST. -- Apr 14 14:33:00 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:00 volumio go-librespot[4107]: time="2024-04-14T14:33:00+08:00" level=debug msg="new websocket client" Apr 14 14:33:00 volumio volumio[3561]: info: Connection to go-librespot Websocket established Apr 14 14:33:00 volumio go-librespot[4107]: time="2024-04-14T14:33:00+08:00" level=debug msg="obtained new client token: AADItL8JJ6g/o+WPpsOMJOteZNa0WIeya2o8cybNsV+S/W98wdgBKuM149Eg0cR35zhQ2k1JXZdYgEhLQs2YJvEiVOeNlK0AzRr7NC4VPEU2hMVFhBUQmb92JrrIGoIs3Pj0VnANbJVbt+865l7gjP53e8redhLq4Vmi0T7AhMLT1IbuaBfHg5WMjzY4tUXeRaZcL8/gw599DwOHhc9P0jiRO4W/WGiOTcrbzzrDSVd0Qe/Y2GR9rH+VxRdIiA==" Apr 14 14:33:00 volumio go-librespot[4107]: time="2024-04-14T14:33: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 14:33:00 volumio go-librespot[4107]: time="2024-04-14T14:33:00+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:01 volumio go-librespot[4107]: time="2024-04-14T14:33:01+08:00" level=debug msg="completed challenge" Apr 14 14:33:01 volumio go-librespot[4107]: time="2024-04-14T14:33:01+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: TravelRestriction" Apr 14 14:33:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:01 volumio volumio[3561]: info: Connection to go-librespot Websocket closed Apr 14 14:33:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:03 volumio volumio[3561]: info: Getting Spotify volume Apr 14 14:33:03 volumio volumio[3561]: (node:3561) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:03 volumio volumio[3561]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 14:33:03 volumio volumio[3561]: (node:3561) 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: 7) Apr 14 14:33:03 volumio volumio[3561]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 14 14:33:03 volumio volumio[3561]: info: CoreCommandRouter::volumioGetState Apr 14 14:33:03 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:04 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:04 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:04 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 94. Apr 14 14:33:04 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:04 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:04 volumio go-librespot[4115]: Librespot-go daemon starting... Apr 14 14:33:04 volumio go-librespot[4115]: time="2024-04-14T14:33:04+08:00" level=info msg="generated new device id: 2fac4de09d9143c5e67ec564563f4191c9280853" Apr 14 14:33:04 volumio go-librespot[4115]: time="2024-04-14T14:33:04+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:05 volumio go-librespot[4115]: time="2024-04-14T14:33:05+08:00" level=debug msg="obtained new client token: AACFOE+YB1J9lMqpwfX+PlR30atRVaR1yIejaFpWTHpMWYJabHFPnnXo2hKV0DrBUMu02Yeks6OC58zS8Ga9iiwALKjJ+sU/355RsjLgBZQ5pIAs1NvTH/wPUUcffixzrKEai2Vh1Nf0qYtORPzVqZk9kXq+omA+Jff+ySDlX42UcNQ+RGbcrDPYzhMmiq14Ap+HOxbCwdFulg0JHlG/dwbLFvAlc/BDQ0hFUVvO1LFCSOiogm+yk+fPRhN8xD7a" Apr 14 14:33:05 volumio go-librespot[4115]: time="2024-04-14T14:33:05+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 14 14:33:06 volumio go-librespot[4115]: time="2024-04-14T14:33:06+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:06 volumio go-librespot[4115]: time="2024-04-14T14:33:06+08:00" level=debug msg="completed challenge" Apr 14 14:33:06 volumio go-librespot[4115]: time="2024-04-14T14:33:06+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: TravelRestriction" Apr 14 14:33:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:07 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:07 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 95. Apr 14 14:33:10 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:10 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:10 volumio go-librespot[4123]: Librespot-go daemon starting... Apr 14 14:33:10 volumio go-librespot[4123]: time="2024-04-14T14:33:10+08:00" level=info msg="generated new device id: 13386328fd7ef194472352b9870ffcb0c11964a6" Apr 14 14:33:10 volumio go-librespot[4123]: time="2024-04-14T14:33:10+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:10 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:10 volumio go-librespot[4123]: time="2024-04-14T14:33:10+08:00" level=debug msg="new websocket client" Apr 14 14:33:10 volumio volumio[3561]: info: Connection to go-librespot Websocket established Apr 14 14:33:10 volumio go-librespot[4123]: time="2024-04-14T14:33:10+08:00" level=debug msg="obtained new client token: AABjVCuxXiNs3eQ3kHA5cs1t5+xNNu5S3I8GlSYR8FK++bK81LcXX2zUtVbhfnAekesj1CEqyVDBmFD5Xsa9bXJ8lil35ZtI02vAM0duyljMVo1Lv5DFKoJ1TCn6GNBeaeJuZBphK2vwX+xgjY9+U0OdOTIbPluEkx1GdsMLxu2h6dhaOm+/+031zZJrRNiDoWpaekBhPuloJtuuMq84wHzDsNBxPVSa0mKULMWF1nGuUta7wyadb6ElEXzismi6" Apr 14 14:33:11 volumio go-librespot[4123]: time="2024-04-14T14:33:11+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 14 14:33:11 volumio go-librespot[4123]: time="2024-04-14T14:33:11+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:11 volumio go-librespot[4123]: time="2024-04-14T14:33:11+08:00" level=debug msg="completed challenge" Apr 14 14:33:11 volumio volumio[3561]: info: Apr 14 14:33:11 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:11 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:11 volumio volumio[3561]: info: Apr 14 14:33:11 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:11 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:11 volumio volumio[3561]: info: Apr 14 14:33:11 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:11 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:11 volumio volumio[3561]: info: Apr 14 14:33:11 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:11 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:11 volumio volumio[3561]: info: Apr 14 14:33:11 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:11 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:11 volumio volumio[3561]: info: Apr 14 14:33:11 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:11 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:11 volumio volumio[3561]: info: ------------------------------ 13ms Apr 14 14:33:11 volumio volumio[3561]: info: sendMpdCommand status took 11 milliseconds Apr 14 14:33:11 volumio volumio[3561]: info: ------------------------------ 10ms Apr 14 14:33:11 volumio volumio[3561]: info: sendMpdCommand status took 9 milliseconds Apr 14 14:33:11 volumio volumio[3561]: info: ------------------------------ 6ms Apr 14 14:33:11 volumio volumio[3561]: info: sendMpdCommand status took 3 milliseconds Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:11 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 14 14:33:11 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 14 14:33:11 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:11 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:11 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:11 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:11 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":69826,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Verkehrsservice","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:11 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:11 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:11 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:11 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:11 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":69826,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Verkehrsservice","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:11 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:11 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:11 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:11 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:11 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":69826,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Verkehrsservice","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:11 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:11 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:11 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:12 volumio go-librespot[4123]: time="2024-04-14T14:33:12+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: TravelRestriction" Apr 14 14:33:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:12 volumio volumio[3561]: info: ------------------------------ 145ms Apr 14 14:33:12 volumio volumio[3561]: info: ------------------------------ 144ms Apr 14 14:33:12 volumio volumio[3561]: info: ------------------------------ 140ms Apr 14 14:33:12 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:12 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:12 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:12 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:12 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:12 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:12 volumio volumio[3561]: info: Connection to go-librespot Websocket closed Apr 14 14:33:13 volumio volumio[3561]: info: Getting Spotify volume Apr 14 14:33:13 volumio volumio[3561]: (node:3561) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:13 volumio volumio[3561]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 14:33:13 volumio volumio[3561]: (node:3561) 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: 8) Apr 14 14:33:13 volumio volumio[3561]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 14:33:13 volumio volumio[3561]: info: CoreCommandRouter::volumioGetState Apr 14 14:33:13 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:14 volumio volumio[3561]: info: Apr 14 14:33:14 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:14 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:14 volumio volumio[3561]: info: Apr 14 14:33:14 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:14 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:14 volumio volumio[3561]: info: Apr 14 14:33:14 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:14 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:14 volumio volumio[3561]: info: Apr 14 14:33:14 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:14 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:14 volumio volumio[3561]: info: Apr 14 14:33:14 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:14 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:14 volumio volumio[3561]: info: Apr 14 14:33:14 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:14 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:14 volumio volumio[3561]: info: ------------------------------ 23ms Apr 14 14:33:14 volumio volumio[3561]: info: sendMpdCommand status took 23 milliseconds Apr 14 14:33:14 volumio volumio[3561]: info: ------------------------------ 22ms Apr 14 14:33:14 volumio volumio[3561]: info: sendMpdCommand status took 18 milliseconds Apr 14 14:33:14 volumio volumio[3561]: info: ------------------------------ 14ms Apr 14 14:33:14 volumio volumio[3561]: info: sendMpdCommand status took 12 milliseconds Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:14 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 14 14:33:14 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 14 14:33:14 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:14 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:14 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:14 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:14 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":72801,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Verkehrsservice","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:14 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:14 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:14 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:14 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:14 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":72801,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Verkehrsservice","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:14 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:14 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:14 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:14 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:14 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":72801,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Verkehrsservice","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:14 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:14 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:14 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:15 volumio volumio[3561]: info: ------------------------------ 138ms Apr 14 14:33:15 volumio volumio[3561]: info: ------------------------------ 136ms Apr 14 14:33:15 volumio volumio[3561]: info: ------------------------------ 129ms Apr 14 14:33:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:15 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:15 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 96. Apr 14 14:33:15 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:15 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:15 volumio go-librespot[4144]: Librespot-go daemon starting... Apr 14 14:33:15 volumio go-librespot[4144]: time="2024-04-14T14:33:15+08:00" level=info msg="generated new device id: 627c88d76e849858d21e8e070d534a2b78eb9b2c" Apr 14 14:33:15 volumio go-librespot[4144]: time="2024-04-14T14:33:15+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:16 volumio go-librespot[4144]: time="2024-04-14T14:33:16+08:00" level=debug msg="obtained new client token: AACr8ckFKMNvRYXgY3w+F4qwSf1ln/nG9lF1WjK6jdJzvPNFTlt2U2HOQqXOSIKJk1lN8ZdCPRjTI9mHqgl7+azV69POOOEolR0T8M2QLk/8HzHDNnfND0tjqYWgVg7GsN96RrG4o2MieK80w/HAyg2cHpPrDV0vba+QJ5g4pel/RHHI93sDXh7VWRbAqcfi2r5hNYcGKKmiDmcViWPwp12/tVMDP48i/b6/274RaAisqOqU0xxhtd/daRld9d7h" Apr 14 14:33:16 volumio go-librespot[4144]: time="2024-04-14T14:33:16+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 14 14:33:16 volumio go-librespot[4144]: time="2024-04-14T14:33:16+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:17 volumio go-librespot[4144]: time="2024-04-14T14:33:17+08:00" level=debug msg="completed challenge" Apr 14 14:33:17 volumio go-librespot[4144]: time="2024-04-14T14:33:17+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: TravelRestriction" Apr 14 14:33:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:18 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:18 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:20 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 97. Apr 14 14:33:20 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:20 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:20 volumio go-librespot[4152]: Librespot-go daemon starting... Apr 14 14:33:20 volumio go-librespot[4152]: time="2024-04-14T14:33:20+08:00" level=info msg="generated new device id: d03f96ff0662e059efef8f7703a0d00228e17d70" Apr 14 14:33:20 volumio go-librespot[4152]: time="2024-04-14T14:33:20+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:21 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:21 volumio volumio[3561]: info: Connection to go-librespot Websocket established Apr 14 14:33:21 volumio go-librespot[4152]: time="2024-04-14T14:33:21+08:00" level=debug msg="new websocket client" Apr 14 14:33:21 volumio go-librespot[4152]: time="2024-04-14T14:33:21+08:00" level=debug msg="obtained new client token: AAAG/ef1HmqJwnmC/0kU3dPfojkgP9/elbKYyy/3ZKCCPrN2BxV8EZCBl44YGl+LOIXMJt2QT6q846eKJXz1ie92txfxkfDw7f1siI75JhpezhAadPuK75fVdodnCRd4vg0eJlF0PrW91Yx3+XQrzIm/63e5+3UBbeFSQwvSSUCk44GjRPbt/svacDiW2S6dB7tEpleuM9u+IiGVObaF+J95FxzR3VuyMnW0C7Orl2fO1h9Jtvf18xcNe9XxiYep" Apr 14 14:33:22 volumio go-librespot[4152]: time="2024-04-14T14:33: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 14:33:22 volumio go-librespot[4152]: time="2024-04-14T14:33:22+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:22 volumio go-librespot[4152]: time="2024-04-14T14:33:22+08:00" level=debug msg="completed challenge" Apr 14 14:33:22 volumio go-librespot[4152]: time="2024-04-14T14:33:22+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: TravelRestriction" Apr 14 14:33:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:22 volumio volumio[3561]: info: Connection to go-librespot Websocket closed Apr 14 14:33:24 volumio volumio[3561]: info: Getting Spotify volume Apr 14 14:33:24 volumio volumio[3561]: (node:3561) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:24 volumio volumio[3561]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 14:33:24 volumio volumio[3561]: (node:3561) 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: 9) Apr 14 14:33:24 volumio volumio[3561]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 14:33:24 volumio volumio[3561]: info: CoreCommandRouter::volumioGetState Apr 14 14:33:24 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:25 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:25 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 98. Apr 14 14:33:26 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:26 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:26 volumio go-librespot[4161]: Librespot-go daemon starting... Apr 14 14:33:26 volumio go-librespot[4161]: time="2024-04-14T14:33:26+08:00" level=info msg="generated new device id: c3153c4df726b998fc45bcb7653dfb384dd3aa36" Apr 14 14:33:26 volumio go-librespot[4161]: time="2024-04-14T14:33:26+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:26 volumio go-librespot[4161]: time="2024-04-14T14:33:26+08:00" level=debug msg="obtained new client token: AAAcFXG776pPgS4QPkTme5ahDWaqbSxJ8ynZQH8Pj1e51z4PB1JtDh8roSr0j1ji2NkasDpcCvUeTvOYjGZrpTYdWYtPOJ1G2vQxv6FsKgkpovuJQJ1uYUnhPs2c7k1K5B5wWb1PyzVTOHsnDPc8MMtuncrZxVzjWLSNftO99onI/zTveeia+S91EV/czieGfs2H3XLcJWtx9tgv3q+uGk+/2gF08uUSxgKpjD2ocHpMbLC6YavpKDWHg2GgO9Ji" Apr 14 14:33:27 volumio go-librespot[4161]: time="2024-04-14T14:33:27+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 14 14:33:27 volumio go-librespot[4161]: time="2024-04-14T14:33:27+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:28 volumio go-librespot[4161]: time="2024-04-14T14:33:28+08:00" level=debug msg="completed challenge" Apr 14 14:33:28 volumio go-librespot[4161]: time="2024-04-14T14:33: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: TravelRestriction" Apr 14 14:33:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:28 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:28 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:31 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 99. Apr 14 14:33:31 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:31 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:31 volumio go-librespot[4171]: Librespot-go daemon starting... Apr 14 14:33:31 volumio go-librespot[4171]: time="2024-04-14T14:33:31+08:00" level=info msg="generated new device id: d8c69af0a0915914e8ebb026019066fe8d805bc3" Apr 14 14:33:31 volumio go-librespot[4171]: time="2024-04-14T14:33:31+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:31 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:31 volumio volumio[3561]: info: Connection to go-librespot Websocket established Apr 14 14:33:31 volumio go-librespot[4171]: time="2024-04-14T14:33:31+08:00" level=debug msg="new websocket client" Apr 14 14:33:32 volumio go-librespot[4171]: time="2024-04-14T14:33:32+08:00" level=debug msg="obtained new client token: AAAeh0Z+cNmbTWZvO3wL8w7YVa3WyZwTsDmvwzoOeUlz5Bf1IsuHZNp0oPT5x2BS9WNqt59s02uPNSZwGxS8ifqYjxDk4XMhh2n8lLOdpHaauOfxvV1J/dTEBZqSiUyM/a5kLilkANmsuaL7H3HFEqN8Mk1F3U3rW7FKIUFA45pMhJGMiQvGpWSt77zrIuGwsH2QGIX6XDhclbZiTtDlBCY/G2/qv+gJW2WbvSdxttzHrHWWy4Nw0BA0tmED+l6M" Apr 14 14:33:32 volumio go-librespot[4171]: time="2024-04-14T14:33: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 14 14:33:32 volumio go-librespot[4171]: time="2024-04-14T14:33:32+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:33 volumio go-librespot[4171]: time="2024-04-14T14:33:33+08:00" level=debug msg="completed challenge" Apr 14 14:33:33 volumio go-librespot[4171]: time="2024-04-14T14:33: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: TravelRestriction" Apr 14 14:33:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:33 volumio volumio[3561]: info: Connection to go-librespot Websocket closed Apr 14 14:33:34 volumio volumio[3561]: info: Getting Spotify volume Apr 14 14:33:34 volumio volumio[3561]: (node:3561) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:34 volumio volumio[3561]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 14:33:34 volumio volumio[3561]: (node:3561) 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: 10) Apr 14 14:33:34 volumio volumio[3561]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 14:33:34 volumio volumio[3561]: info: CoreCommandRouter::volumioGetState Apr 14 14:33:34 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:36 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:36 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 100. Apr 14 14:33:36 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:36 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:36 volumio go-librespot[4181]: Librespot-go daemon starting... Apr 14 14:33:36 volumio go-librespot[4181]: time="2024-04-14T14:33:36+08:00" level=info msg="generated new device id: ee6d6c830085b88912d9841836553a526ad5ed39" Apr 14 14:33:36 volumio go-librespot[4181]: time="2024-04-14T14:33:36+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:37 volumio go-librespot[4181]: time="2024-04-14T14:33:37+08:00" level=debug msg="obtained new client token: AAAxYH5XwX8I5np4FEay7JzcIC1SSzQwDxiHQHKZl8jCOkCjml4WkEREovRmOLVHD8E4NFh886wSJpb2cv436sKgwVkoJWaV6I4958mydc1+d1Bg6TUrRAoVZLzS8sf6J84OqCgkccr64yDww1LYhbmwguP69UIODMgO9ia4wf/32LB6Xl2Pd5kEVp+UmLH8zwinCOlxuDV3Zb4aVO6EJfqJnN7wfBz4my0xdbedwCwrnXYjOgMC0zQlOyXfuQ==" Apr 14 14:33:37 volumio go-librespot[4181]: time="2024-04-14T14:33: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 14:33:37 volumio go-librespot[4181]: time="2024-04-14T14:33:37+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:38 volumio go-librespot[4181]: time="2024-04-14T14:33:38+08:00" level=debug msg="completed challenge" Apr 14 14:33:38 volumio go-librespot[4181]: time="2024-04-14T14:33: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: TravelRestriction" Apr 14 14:33:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:39 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:39 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:41 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 101. Apr 14 14:33:41 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:41 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:41 volumio go-librespot[4230]: Librespot-go daemon starting... Apr 14 14:33:41 volumio go-librespot[4230]: time="2024-04-14T14:33:41+08:00" level=info msg="generated new device id: a0f1df25fb5baf35bf9bf9275fa8925b21c8e3a3" Apr 14 14:33:41 volumio go-librespot[4230]: time="2024-04-14T14:33:41+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:42 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:42 volumio go-librespot[4230]: time="2024-04-14T14:33:42+08:00" level=debug msg="new websocket client" Apr 14 14:33:42 volumio volumio[3561]: info: Connection to go-librespot Websocket established Apr 14 14:33:42 volumio go-librespot[4230]: time="2024-04-14T14:33:42+08:00" level=debug msg="obtained new client token: AACxR86I7uQwxHQBtCXIT4Lwt3B3LE91hrHS+e6FNgwaoCX9Gl/emTsct0TA8k4GqfpXApQ1hXaN+KGYvT64UMf5Y7xEiItzWxShMq0pwBV9bLWNZQDbNE10434YBmqJYc7fn+aHBznmr4cyP+2Y/F5l8mbwf2dg+WAGzgcW/govoBdFODAqqc4gNJnc5o57dk4vRZjglmYJkZ2E5xCLecBIgMcCQwE/+RY7tfGoaP3SMJsdy35lc4oT/pqPhq/7" Apr 14 14:33:42 volumio go-librespot[4230]: time="2024-04-14T14:33:42+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 14 14:33:43 volumio go-librespot[4230]: time="2024-04-14T14:33:43+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:43 volumio go-librespot[4230]: time="2024-04-14T14:33:43+08:00" level=debug msg="completed challenge" Apr 14 14:33:43 volumio go-librespot[4230]: time="2024-04-14T14:33: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: TravelRestriction" Apr 14 14:33:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:43 volumio volumio[3561]: info: Connection to go-librespot Websocket closed Apr 14 14:33:45 volumio volumio[3561]: info: Getting Spotify volume Apr 14 14:33:45 volumio volumio[3561]: (node:3561) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:45 volumio volumio[3561]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 14:33:45 volumio volumio[3561]: (node:3561) 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: 11) Apr 14 14:33:45 volumio volumio[3561]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 14:33:45 volumio volumio[3561]: info: CoreCommandRouter::volumioGetState Apr 14 14:33:45 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:46 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:46 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 102. Apr 14 14:33:47 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:47 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:47 volumio go-librespot[4238]: Librespot-go daemon starting... Apr 14 14:33:47 volumio go-librespot[4238]: time="2024-04-14T14:33:47+08:00" level=info msg="generated new device id: b93746c39c9fc58e2731f363b21da464413ecf87" Apr 14 14:33:47 volumio go-librespot[4238]: time="2024-04-14T14:33:47+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:47 volumio volumio[3561]: info: Apr 14 14:33:47 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:47 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:47 volumio volumio[3561]: info: Apr 14 14:33:47 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:47 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:47 volumio volumio[3561]: info: Apr 14 14:33:47 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:47 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:47 volumio volumio[3561]: info: Apr 14 14:33:47 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:47 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:47 volumio volumio[3561]: info: Apr 14 14:33:47 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:47 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:47 volumio volumio[3561]: info: Apr 14 14:33:47 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:47 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:47 volumio volumio[3561]: info: ------------------------------ 8ms Apr 14 14:33:47 volumio volumio[3561]: info: sendMpdCommand status took 7 milliseconds Apr 14 14:33:47 volumio volumio[3561]: info: ------------------------------ 6ms Apr 14 14:33:47 volumio volumio[3561]: info: sendMpdCommand status took 5 milliseconds Apr 14 14:33:47 volumio volumio[3561]: info: ------------------------------ 4ms Apr 14 14:33:47 volumio volumio[3561]: info: sendMpdCommand status took 4 milliseconds Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:47 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 14 14:33:47 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 14 14:33:47 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:47 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:47 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:47 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:47 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":105495,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Alle aktuellen Hits","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:47 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:47 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:47 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:47 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:47 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":105495,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Alle aktuellen Hits","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:47 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:47 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:47 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:47 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:47 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":105495,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Alle aktuellen Hits","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:47 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:47 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:47 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:47 volumio go-librespot[4238]: time="2024-04-14T14:33:47+08:00" level=debug msg="obtained new client token: AAB72VoIMJVZvMATldnqpTeV5UxhS/zAGrTcUOfk/9gQWqITUGz6FTEw7BBGoiBpAEjwkOM2ygH+7oSpt/kGwM6ZJa5M4JGEEd9ihrD39tBpoYoUSuU0N0LJSsMrI4rfRh/WzRG31cynY5PzjHN8rtnnRZljSFABCzVDb2YXfCydc0GJKLIRX2KzwYY72dvH9tByoG8CAtGkl7UEze6Ow4TjyAUR87PMKqW+ugpSOYJSjAh5kGk4S1/SQhNxCDoz" Apr 14 14:33:47 volumio volumio[3561]: info: ------------------------------ 167ms Apr 14 14:33:47 volumio volumio[3561]: info: ------------------------------ 165ms Apr 14 14:33:47 volumio volumio[3561]: info: ------------------------------ 164ms Apr 14 14:33:47 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:47 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:47 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:47 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:47 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:47 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:48 volumio go-librespot[4238]: time="2024-04-14T14:33:48+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 14 14:33:48 volumio go-librespot[4238]: time="2024-04-14T14:33:48+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:49 volumio go-librespot[4238]: time="2024-04-14T14:33:49+08:00" level=debug msg="completed challenge" Apr 14 14:33:49 volumio go-librespot[4238]: time="2024-04-14T14:33:49+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: TravelRestriction" Apr 14 14:33:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:49 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:49 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:49 volumio volumio[3561]: info: Apr 14 14:33:49 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:49 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:49 volumio volumio[3561]: info: Apr 14 14:33:49 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:49 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:49 volumio volumio[3561]: info: Apr 14 14:33:49 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:49 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:49 volumio volumio[3561]: info: Apr 14 14:33:49 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:49 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:49 volumio volumio[3561]: info: Apr 14 14:33:49 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:33:49 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:33:49 volumio volumio[3561]: info: Apr 14 14:33:49 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:33:49 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:33:49 volumio volumio[3561]: info: ------------------------------ 13ms Apr 14 14:33:49 volumio volumio[3561]: info: sendMpdCommand status took 10 milliseconds Apr 14 14:33:49 volumio volumio[3561]: info: ------------------------------ 10ms Apr 14 14:33:49 volumio volumio[3561]: info: sendMpdCommand status took 9 milliseconds Apr 14 14:33:49 volumio volumio[3561]: info: ------------------------------ 8ms Apr 14 14:33:49 volumio volumio[3561]: info: sendMpdCommand status took 6 milliseconds Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:33:49 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 14 14:33:49 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 14 14:33:49 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:49 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:33:49 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:49 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:49 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":107727,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Alle aktuellen Hits","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:49 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:49 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:49 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:49 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:49 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":107727,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Alle aktuellen Hits","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:49 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:49 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:49 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:33:49 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:33:49 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":107727,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"ANTENNE BAYERN - Alle aktuellen Hits","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:33:49 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:33:49 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:33:49 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:33:49 volumio volumio[3561]: info: ------------------------------ 137ms Apr 14 14:33:49 volumio volumio[3561]: info: ------------------------------ 134ms Apr 14 14:33:49 volumio volumio[3561]: info: ------------------------------ 133ms Apr 14 14:33:50 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:50 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:50 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:50 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:50 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:50 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:52 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 103. Apr 14 14:33:52 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:52 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:52 volumio go-librespot[4259]: Librespot-go daemon starting... Apr 14 14:33:52 volumio go-librespot[4259]: time="2024-04-14T14:33:52+08:00" level=info msg="generated new device id: 90229620f3d889ea579caec8fbeb97870a818e42" Apr 14 14:33:52 volumio go-librespot[4259]: time="2024-04-14T14:33:52+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:52 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:52 volumio go-librespot[4259]: time="2024-04-14T14:33:52+08:00" level=debug msg="new websocket client" Apr 14 14:33:52 volumio volumio[3561]: info: Connection to go-librespot Websocket established Apr 14 14:33:52 volumio go-librespot[4259]: time="2024-04-14T14:33:52+08:00" level=debug msg="obtained new client token: AAAQl2rS1SqfhnDWZDQ+5fVNsS0glEgmZC/7cI+H8Hj/Ux3Zf+EZbBRuIiNXQr6riemlZy1Aq95deCpfOgxOwtCE+ujYGHG5+pXbNWVR4yXP1IhD5PwDm3kYrQcw8jMybT2Dn5uBxOJNCm4DtxmHOlIxzBMBF+XAcoCIVFady+LUUNflvr6F5uKFNrSAfJVSa+SAfpp6K5UirqNpIPDOxDtSSarTipFON2XE5qy12aHzKzfSr/n3I3fMmNGnKFYL" Apr 14 14:33:53 volumio go-librespot[4259]: time="2024-04-14T14:33:53+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 14 14:33:53 volumio go-librespot[4259]: time="2024-04-14T14:33:53+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:54 volumio go-librespot[4259]: time="2024-04-14T14:33:54+08:00" level=debug msg="completed challenge" Apr 14 14:33:54 volumio go-librespot[4259]: time="2024-04-14T14:33:54+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: TravelRestriction" Apr 14 14:33:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:33:54 volumio volumio[3561]: info: Connection to go-librespot Websocket closed Apr 14 14:33:55 volumio volumio[3561]: info: Getting Spotify volume Apr 14 14:33:55 volumio volumio[3561]: (node:3561) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:55 volumio volumio[3561]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 14:33:55 volumio volumio[3561]: (node:3561) 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: 12) Apr 14 14:33:55 volumio volumio[3561]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 14:33:55 volumio volumio[3561]: info: CoreCommandRouter::volumioGetState Apr 14 14:33:55 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:33:57 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:33:57 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:33:57 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:33:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 104. Apr 14 14:33:57 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:33:57 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:33:57 volumio go-librespot[4268]: Librespot-go daemon starting... Apr 14 14:33:57 volumio go-librespot[4268]: time="2024-04-14T14:33:57+08:00" level=info msg="generated new device id: afd8ceb8156b9126b4a25aed0a335595878d4d9a" Apr 14 14:33:57 volumio go-librespot[4268]: time="2024-04-14T14:33:57+08:00" level=debug msg="stored credentials not found" Apr 14 14:33:58 volumio go-librespot[4268]: time="2024-04-14T14:33:58+08:00" level=debug msg="obtained new client token: AACDBtbsJ0nkE6ajfPLbpB83NG+UMIYB4xI5g3F8tZAxnrIARNSA+bmbX0wu/rCfc2XyWxN0r7UNrOuUy72JyOYnwQiNcchZmbj+iaLjcb8j8S6HPE+vHbMt8JI6oHqBnd/ambkSkCho9zSWDYGnG9O9kfWJJsu8j8aY9QlJG+a8m1p93KjmzM/xtuqtOZYQsPaZ9yNeI7D0Zh3Xx7N9GWOuEV7vLlToX0PjnnxCFI3qe72sroRjB1g1ZplbEw==" Apr 14 14:33:59 volumio go-librespot[4268]: time="2024-04-14T14:33:59+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 14 14:33:59 volumio go-librespot[4268]: time="2024-04-14T14:33:59+08:00" level=debug msg="completed keyexchange" Apr 14 14:33:59 volumio go-librespot[4268]: time="2024-04-14T14:33:59+08:00" level=debug msg="completed challenge" Apr 14 14:33:59 volumio go-librespot[4268]: time="2024-04-14T14:33:59+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: TravelRestriction" Apr 14 14:33:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:33:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:34:00 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:34:00 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:34:01 volumio ntpd[665]: 95.111.202.5 local addr 192.168.2.3 -> Apr 14 14:34:01 volumio volumio[3561]: error: [yt-cast-receiver] (YouTube Music) Error occurred in SendMessageTask: Apr 14 14:34:01 volumio volumio[3561]: LoungeScreenDisconnected { Apr 14 14:34:01 volumio volumio[3561]: AID: null, Apr 14 14:34:01 volumio volumio[3561]: name: 'loungeScreenDisconnected', Apr 14 14:34:01 volumio volumio[3561]: payload: {} Apr 14 14:34:01 volumio volumio[3561]: } Apr 14 14:34:01 volumio volumio[3561]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 14 14:34:01 volumio volumio[3561]: Stack trace: Apr 14 14:34:01 volumio volumio[3561]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 14 14:34:01 volumio volumio[3561]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 14 14:34:01 volumio volumio[3561]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 14 14:34:01 volumio volumio[3561]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 14 14:34:01 volumio volumio[3561]: at AsyncTaskQueue.push (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:39:18) Apr 14 14:34:01 volumio volumio[3561]: at /data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:339:67 Apr 14 14:34:01 volumio volumio[3561]: at new Promise () Apr 14 14:34:01 volumio volumio[3561]: at Session.sendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:338:16) Apr 14 14:34:01 volumio volumio[3561]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:236:28) Apr 14 14:34:01 volumio volumio[3561]: at Session.begin (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:207:26) Apr 14 14:34:01 volumio volumio[3561]: at runMicrotasks () Apr 14 14:34:01 volumio volumio[3561]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 14 14:34:01 volumio volumio[3561]: at async Promise.all (index 1) Apr 14 14:34:01 volumio volumio[3561]: at async YouTubeApp.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/YouTubeApp.js:110:13) Apr 14 14:34:01 volumio volumio[3561]: at async YouTubeCastReceiver.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/YouTubeCastReceiver.js:91:13) Apr 14 14:34:01 volumio volumio[3561]: error: [yt-cast-receiver] Failed to start receiver: Apr 14 14:34:01 volumio volumio[3561]: (AppError) Failed to start YouTubeApp Apr 14 14:34:01 volumio volumio[3561]: --->(SessionError) (YouTube Music) Failed to establish session Apr 14 14:34:01 volumio volumio[3561]: ------>(ConnectionError) (YouTube Music) Connection error in generating screen Id Apr 14 14:34:01 volumio volumio[3561]: Error info: { Apr 14 14:34:01 volumio volumio[3561]: url: 'https://www.youtube.com/api/lounge/pairing/generate_screen_id' Apr 14 14:34:01 volumio volumio[3561]: } Apr 14 14:34:01 volumio volumio[3561]: --------->(FetchError) request to https://www.youtube.com/api/lounge/pairing/generate_screen_id failed, reason: connect ETIMEDOUT 199.96.63.163:443 Apr 14 14:34:01 volumio volumio[3561]: Stack trace: Apr 14 14:34:01 volumio volumio[3561]: AppError: Failed to start YouTubeApp Apr 14 14:34:01 volumio volumio[3561]: at YouTubeApp.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/YouTubeApp.js:125:19) Apr 14 14:34:01 volumio volumio[3561]: at runMicrotasks () Apr 14 14:34:01 volumio volumio[3561]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 14 14:34:01 volumio volumio[3561]: at async YouTubeCastReceiver.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/YouTubeCastReceiver.js:91:13) Apr 14 14:34:01 volumio volumio[3561]: error: [yt-cast-receiver] (YouTube) Error occurred in SendMessageTask: Apr 14 14:34:01 volumio volumio[3561]: LoungeScreenDisconnected { Apr 14 14:34:01 volumio volumio[3561]: AID: null, Apr 14 14:34:01 volumio volumio[3561]: name: 'loungeScreenDisconnected', Apr 14 14:34:01 volumio volumio[3561]: payload: {} Apr 14 14:34:01 volumio volumio[3561]: } Apr 14 14:34:01 volumio volumio[3561]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 14 14:34:01 volumio volumio[3561]: Stack trace: Apr 14 14:34:01 volumio volumio[3561]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 14 14:34:01 volumio volumio[3561]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 14 14:34:01 volumio volumio[3561]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 14 14:34:01 volumio volumio[3561]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 14 14:34:01 volumio volumio[3561]: at AsyncTaskQueue.push (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:39:18) Apr 14 14:34:01 volumio volumio[3561]: at /data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:339:67 Apr 14 14:34:01 volumio volumio[3561]: at new Promise () Apr 14 14:34:01 volumio volumio[3561]: at Session.sendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:338:16) Apr 14 14:34:01 volumio volumio[3561]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:236:28) Apr 14 14:34:01 volumio volumio[3561]: at /data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/YouTubeApp.js:118:35 Apr 14 14:34:01 volumio volumio[3561]: at Array.forEach () Apr 14 14:34:01 volumio volumio[3561]: at YouTubeApp.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/YouTubeApp.js:114:24) Apr 14 14:34:01 volumio volumio[3561]: at runMicrotasks () Apr 14 14:34:01 volumio volumio[3561]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 14 14:34:01 volumio volumio[3561]: at async YouTubeCastReceiver.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/YouTubeCastReceiver.js:91:13) Apr 14 14:34:01 volumio volumio[3561]: error: [yt-cast-receiver] (YouTube Music) Error occurred in SendMessageTask: Apr 14 14:34:01 volumio volumio[3561]: LoungeScreenDisconnected { Apr 14 14:34:01 volumio volumio[3561]: AID: null, Apr 14 14:34:01 volumio volumio[3561]: name: 'loungeScreenDisconnected', Apr 14 14:34:01 volumio volumio[3561]: payload: {} Apr 14 14:34:01 volumio volumio[3561]: } Apr 14 14:34:01 volumio volumio[3561]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 14 14:34:01 volumio volumio[3561]: Stack trace: Apr 14 14:34:01 volumio volumio[3561]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 14 14:34:01 volumio volumio[3561]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 14 14:34:01 volumio volumio[3561]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 14 14:34:01 volumio volumio[3561]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 14 14:34:01 volumio volumio[3561]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Apr 14 14:34:01 volumio volumio[3561]: at runMicrotasks () Apr 14 14:34:01 volumio volumio[3561]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 14 14:34:01 volumio volumio[3561]: error: [ytcr] Failed to start plugin: Apr 14 14:34:01 volumio volumio[3561]: (AppError) Failed to start YouTubeApp Apr 14 14:34:01 volumio volumio[3561]: --->(SessionError) (YouTube Music) Failed to establish session Apr 14 14:34:01 volumio volumio[3561]: ------>(ConnectionError) (YouTube Music) Connection error in generating screen Id Apr 14 14:34:01 volumio volumio[3561]: Error info: { Apr 14 14:34:01 volumio volumio[3561]: url: 'https://www.youtube.com/api/lounge/pairing/generate_screen_id' Apr 14 14:34:01 volumio volumio[3561]: } Apr 14 14:34:01 volumio volumio[3561]: --------->(FetchError) request to https://www.youtube.com/api/lounge/pairing/generate_screen_id failed, reason: connect ETIMEDOUT 199.96.63.163:443 Apr 14 14:34:01 volumio volumio[3561]: Stack trace: Apr 14 14:34:01 volumio volumio[3561]: AppError: Failed to start YouTubeApp Apr 14 14:34:01 volumio volumio[3561]: at YouTubeApp.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/YouTubeApp.js:125:19) Apr 14 14:34:01 volumio volumio[3561]: at runMicrotasks () Apr 14 14:34:01 volumio volumio[3561]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 14 14:34:01 volumio volumio[3561]: at async YouTubeCastReceiver.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/YouTubeCastReceiver.js:91:13) Apr 14 14:34:01 volumio volumio[3561]: error: [yt-cast-receiver] (YouTube) Error occurred in SendMessageTask: Apr 14 14:34:01 volumio volumio[3561]: LoungeScreenDisconnected { Apr 14 14:34:01 volumio volumio[3561]: AID: null, Apr 14 14:34:01 volumio volumio[3561]: name: 'loungeScreenDisconnected', Apr 14 14:34:01 volumio volumio[3561]: payload: {} Apr 14 14:34:01 volumio volumio[3561]: } Apr 14 14:34:01 volumio volumio[3561]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 14 14:34:01 volumio volumio[3561]: Stack trace: Apr 14 14:34:01 volumio volumio[3561]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 14 14:34:01 volumio volumio[3561]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 14 14:34:01 volumio volumio[3561]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 14 14:34:01 volumio volumio[3561]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 14 14:34:01 volumio volumio[3561]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Apr 14 14:34:01 volumio volumio[3561]: at runMicrotasks () Apr 14 14:34:01 volumio volumio[3561]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 14 14:34:01 volumio volumio[3561]: at async /data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/YouTubeApp.js:118:21 Apr 14 14:34:01 volumio volumio[3561]: error: [yt-cast-receiver] (YouTube Music) Error occurred in SendMessageTask: Apr 14 14:34:01 volumio volumio[3561]: LoungeScreenDisconnected { Apr 14 14:34:01 volumio volumio[3561]: AID: null, Apr 14 14:34:01 volumio volumio[3561]: name: 'loungeScreenDisconnected', Apr 14 14:34:01 volumio volumio[3561]: payload: {} Apr 14 14:34:01 volumio volumio[3561]: } Apr 14 14:34:01 volumio volumio[3561]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 14 14:34:01 volumio volumio[3561]: Stack trace: Apr 14 14:34:01 volumio volumio[3561]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 14 14:34:01 volumio volumio[3561]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 14 14:34:01 volumio volumio[3561]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 14 14:34:01 volumio volumio[3561]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 14 14:34:01 volumio volumio[3561]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Apr 14 14:34:01 volumio volumio[3561]: at runMicrotasks () Apr 14 14:34:01 volumio volumio[3561]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 14 14:34:01 volumio volumio[3561]: at async /data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/YouTubeApp.js:118:21 Apr 14 14:34:01 volumio volumio[3561]: (node:3561) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Apr 14 14:34:01 volumio volumio[3561]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Apr 14 14:34:01 volumio volumio[3561]: at runMicrotasks () Apr 14 14:34:01 volumio volumio[3561]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 14 14:34:01 volumio volumio[3561]: (node:3561) 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: 19) Apr 14 14:34:01 volumio volumio[3561]: error: [yt-cast-receiver] (YouTube Music) Error occurred in SendMessageTask: Apr 14 14:34:01 volumio volumio[3561]: LoungeScreenDisconnected { Apr 14 14:34:01 volumio volumio[3561]: AID: null, Apr 14 14:34:01 volumio volumio[3561]: name: 'loungeScreenDisconnected', Apr 14 14:34:01 volumio volumio[3561]: payload: {} Apr 14 14:34:01 volumio volumio[3561]: } Apr 14 14:34:01 volumio volumio[3561]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 14 14:34:01 volumio volumio[3561]: Stack trace: Apr 14 14:34:01 volumio volumio[3561]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 14 14:34:01 volumio volumio[3561]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 14 14:34:01 volumio volumio[3561]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 14 14:34:01 volumio volumio[3561]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 14 14:34:01 volumio volumio[3561]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 14 14:34:01 volumio volumio[3561]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Apr 14 14:34:01 volumio volumio[3561]: at runMicrotasks () Apr 14 14:34:01 volumio volumio[3561]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 14 14:34:01 volumio volumio[3561]: (node:3561) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Apr 14 14:34:01 volumio volumio[3561]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Apr 14 14:34:01 volumio volumio[3561]: at runMicrotasks () Apr 14 14:34:01 volumio volumio[3561]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 14 14:34:01 volumio volumio[3561]: (node:3561) 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: 21) Apr 14 14:34:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:34:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 105. Apr 14 14:34:03 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:34:03 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:34:03 volumio go-librespot[4279]: Librespot-go daemon starting... Apr 14 14:34:03 volumio go-librespot[4279]: time="2024-04-14T14:34:03+08:00" level=info msg="generated new device id: ae8e76042b738e5d0a28765e8f885f7fc9d63c46" Apr 14 14:34:03 volumio go-librespot[4279]: time="2024-04-14T14:34:03+08:00" level=debug msg="stored credentials not found" Apr 14 14:34:03 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:34:03 volumio go-librespot[4279]: time="2024-04-14T14:34:03+08:00" level=debug msg="new websocket client" Apr 14 14:34:03 volumio volumio[3561]: info: Connection to go-librespot Websocket established Apr 14 14:34:03 volumio go-librespot[4279]: time="2024-04-14T14:34:03+08:00" level=debug msg="obtained new client token: AADXbVQ/Cs5Rh9EQJRUGNBZ3FTYaTomWqz+sWnGeP2GaC81sCreBjNuis01M50arrHcIAO9crtE+kAgeV9KVnyefc5SSEXG1bbp99QOGMjAolvUc7MqPlDtvWXBwvWYgfbY9et6+1x8f1EPOwARqNinwS1SoDcMxoFHxxk39pCbymgUJ4TBalH38+O0UVNv1dD0Ws96Aoqg6zcbI3YvXJXJZr53AMxD7snmr5CXff6H/HIUmROttW6rSw7jH3kCh" Apr 14 14:34:04 volumio go-librespot[4279]: time="2024-04-14T14:34: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 14:34:04 volumio go-librespot[4279]: time="2024-04-14T14:34:04+08:00" level=debug msg="completed keyexchange" Apr 14 14:34:04 volumio go-librespot[4279]: time="2024-04-14T14:34:04+08:00" level=debug msg="completed challenge" Apr 14 14:34:05 volumio go-librespot[4279]: time="2024-04-14T14:34: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: TravelRestriction" Apr 14 14:34:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:34:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:34:05 volumio volumio[3561]: info: Connection to go-librespot Websocket closed Apr 14 14:34:06 volumio volumio[3561]: info: Getting Spotify volume Apr 14 14:34:06 volumio volumio[3561]: (node:3561) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:34:06 volumio volumio[3561]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 14:34:06 volumio volumio[3561]: (node:3561) 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: 22) Apr 14 14:34:06 volumio volumio[3561]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 14:34:06 volumio volumio[3561]: info: CoreCommandRouter::volumioGetState Apr 14 14:34:06 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:08 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:34:08 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:34:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:34:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 106. Apr 14 14:34:08 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:34:08 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:34:08 volumio go-librespot[4288]: Librespot-go daemon starting... Apr 14 14:34:08 volumio go-librespot[4288]: time="2024-04-14T14:34:08+08:00" level=info msg="generated new device id: 1d00f060c75df15aaf8622701557ef9e91751813" Apr 14 14:34:08 volumio go-librespot[4288]: time="2024-04-14T14:34:08+08:00" level=debug msg="stored credentials not found" Apr 14 14:34:09 volumio go-librespot[4288]: time="2024-04-14T14:34:09+08:00" level=debug msg="obtained new client token: AAAu8UoNGNa/Abufzco/vqwNyvMSTOuLzr5Rz19y4nuNa9UAamVyVdlyx50LroueGY5zCfEJiolDZK1zwlDDza10GMrBniuNW6uVYKb6ksuSNr8+dctpNWa/RktZTP7388rm/zCGNT0NzrCRhLEavPBgqllhBNUiAnXk0N7TdCQOUolucYthvg8rOgSE3tJBBfU+oo1ki5D4sC20K3ihcDyb7B5lKXhQqj65SR4+/eyXp6KIiAyRPfexLbNO/GfG" Apr 14 14:34:10 volumio go-librespot[4288]: time="2024-04-14T14:34:10+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 14 14:34:10 volumio go-librespot[4288]: time="2024-04-14T14:34:10+08:00" level=debug msg="completed keyexchange" Apr 14 14:34:10 volumio go-librespot[4288]: time="2024-04-14T14:34:10+08:00" level=debug msg="completed challenge" Apr 14 14:34:10 volumio go-librespot[4288]: time="2024-04-14T14:34:10+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: TravelRestriction" Apr 14 14:34:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:34:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:34:11 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:34:11 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:34:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:34:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 107. Apr 14 14:34:14 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:34:14 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:34:14 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:34:14 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:34:14 volumio go-librespot[4296]: Librespot-go daemon starting... Apr 14 14:34:14 volumio go-librespot[4296]: time="2024-04-14T14:34:14+08:00" level=info msg="generated new device id: 257b16e2b5b04d9f6be24da0ae954704163f578f" Apr 14 14:34:14 volumio go-librespot[4296]: time="2024-04-14T14:34:14+08:00" level=debug msg="stored credentials not found" Apr 14 14:34:14 volumio go-librespot[4296]: time="2024-04-14T14:34:14+08:00" level=debug msg="obtained new client token: AABBA6FQ8ZszacJ0D5EMr8QKi63+uHvHJUgOjj3Lu9uoTyPoFJ+43AneTJoemvVDDfVe06C9d6RjI/dlcxXJOOF4eGJOThlQ6wNA+TQ5ct150Ic52cgWqJ3w8GyWoCIWnxD3k48ZG8AWcPYmdtrZwmpOWv88/x6YIdTnfzKFi4nXFki/s6LmuBF6/hfn6veO65YXTNTC9Cuti0P7WzFiRj+Soy4opeEOAJqjQWEXdgVwhwr1QQPkxQG8kiyu9z0B" Apr 14 14:34:15 volumio volumio[3561]: info: Apr 14 14:34:15 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:34:15 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:34:15 volumio volumio[3561]: info: Apr 14 14:34:15 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:34:15 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:34:15 volumio volumio[3561]: info: Apr 14 14:34:15 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:34:15 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:34:15 volumio volumio[3561]: info: Apr 14 14:34:15 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:34:15 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:34:15 volumio volumio[3561]: info: Apr 14 14:34:15 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:34:15 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:34:15 volumio volumio[3561]: info: Apr 14 14:34:15 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:34:15 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:34:15 volumio volumio[3561]: info: ------------------------------ 13ms Apr 14 14:34:15 volumio volumio[3561]: info: sendMpdCommand status took 9 milliseconds Apr 14 14:34:15 volumio volumio[3561]: info: ------------------------------ 7ms Apr 14 14:34:15 volumio volumio[3561]: info: sendMpdCommand status took 5 milliseconds Apr 14 14:34:15 volumio volumio[3561]: info: ------------------------------ 4ms Apr 14 14:34:15 volumio volumio[3561]: info: sendMpdCommand status took 2 milliseconds Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:34:15 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 14 14:34:15 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 14 14:34:15 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:34:15 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:34:15 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:34:15 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:34:15 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":132981,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Zara Larsson - Memory Lane","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:34:15 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:34:15 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:15 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:34:15 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:34:15 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":132981,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Zara Larsson - Memory Lane","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:34:15 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:34:15 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:15 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:34:15 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:34:15 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":132981,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Zara Larsson - Memory Lane","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:34:15 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:34:15 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:15 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:15 volumio volumio[3561]: info: ------------------------------ 164ms Apr 14 14:34:15 volumio volumio[3561]: info: ------------------------------ 158ms Apr 14 14:34:15 volumio volumio[3561]: info: ------------------------------ 155ms Apr 14 14:34:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:15 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:16 volumio go-librespot[4296]: time="2024-04-14T14:34:16+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 14 14:34:17 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:34:17 volumio go-librespot[4296]: time="2024-04-14T14:34:17+08:00" level=debug msg="new websocket client" Apr 14 14:34:17 volumio volumio[3561]: info: Connection to go-librespot Websocket established Apr 14 14:34:17 volumio go-librespot[4296]: time="2024-04-14T14:34:17+08:00" level=debug msg="completed keyexchange" Apr 14 14:34:18 volumio volumio[3561]: info: Apr 14 14:34:18 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:34:18 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:34:18 volumio volumio[3561]: info: Apr 14 14:34:18 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:34:18 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:34:18 volumio volumio[3561]: info: Apr 14 14:34:18 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:34:18 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:34:18 volumio volumio[3561]: info: Apr 14 14:34:18 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:34:18 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:34:18 volumio volumio[3561]: info: Apr 14 14:34:18 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:34:18 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:34:18 volumio volumio[3561]: info: Apr 14 14:34:18 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:34:18 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:34:18 volumio volumio[3561]: info: ------------------------------ 10ms Apr 14 14:34:18 volumio volumio[3561]: info: sendMpdCommand status took 6 milliseconds Apr 14 14:34:18 volumio volumio[3561]: info: ------------------------------ 7ms Apr 14 14:34:18 volumio volumio[3561]: info: sendMpdCommand status took 5 milliseconds Apr 14 14:34:18 volumio volumio[3561]: info: ------------------------------ 4ms Apr 14 14:34:18 volumio volumio[3561]: info: sendMpdCommand status took 3 milliseconds Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:34:18 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 14 14:34:18 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 14 14:34:18 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:34:18 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:34:18 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:34:18 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:34:18 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":135962,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Zara Larsson - Memory Lane","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:34:18 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:34:18 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:18 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:34:18 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:34:18 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":135962,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Zara Larsson - Memory Lane","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:34:18 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:34:18 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:18 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:34:18 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:34:18 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":135962,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Zara Larsson - Memory Lane","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:34:18 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:34:18 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:18 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:18 volumio go-librespot[4296]: time="2024-04-14T14:34:18+08:00" level=debug msg="completed challenge" Apr 14 14:34:18 volumio volumio[3561]: info: ------------------------------ 137ms Apr 14 14:34:18 volumio volumio[3561]: info: ------------------------------ 135ms Apr 14 14:34:18 volumio volumio[3561]: info: ------------------------------ 133ms Apr 14 14:34:18 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:18 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:18 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:18 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:18 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:18 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:18 volumio go-librespot[4296]: time="2024-04-14T14:34: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: TravelRestriction" Apr 14 14:34:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:34:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:34:18 volumio volumio[3561]: info: Connection to go-librespot Websocket closed Apr 14 14:34:20 volumio volumio[3561]: info: Getting Spotify volume Apr 14 14:34:20 volumio volumio[3561]: (node:3561) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:34:20 volumio volumio[3561]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 14:34:20 volumio volumio[3561]: (node:3561) 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: 23) Apr 14 14:34:20 volumio volumio[3561]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::volumioGetState Apr 14 14:34:20 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:20 volumio volumio[3561]: info: Apr 14 14:34:20 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:34:20 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:34:20 volumio volumio[3561]: info: Apr 14 14:34:20 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:34:20 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:34:20 volumio volumio[3561]: info: Apr 14 14:34:20 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:34:20 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:34:20 volumio volumio[3561]: info: Apr 14 14:34:20 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:34:20 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:34:20 volumio volumio[3561]: info: Apr 14 14:34:20 volumio volumio[3561]: ---------------------------- MPD announces system playlist update Apr 14 14:34:20 volumio volumio[3561]: info: Ignoring MPD Status Update Apr 14 14:34:20 volumio volumio[3561]: info: Apr 14 14:34:20 volumio volumio[3561]: ---------------------------- MPD announces state update: player Apr 14 14:34:20 volumio volumio[3561]: info: ControllerMpd::getState Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand status Apr 14 14:34:20 volumio volumio[3561]: info: ------------------------------ 11ms Apr 14 14:34:20 volumio volumio[3561]: info: sendMpdCommand status took 6 milliseconds Apr 14 14:34:20 volumio volumio[3561]: info: ------------------------------ 7ms Apr 14 14:34:20 volumio volumio[3561]: info: sendMpdCommand status took 5 milliseconds Apr 14 14:34:20 volumio volumio[3561]: info: ------------------------------ 4ms Apr 14 14:34:20 volumio volumio[3561]: info: sendMpdCommand status took 3 milliseconds Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::parseState Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 14:34:20 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 14 14:34:20 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 8 milliseconds Apr 14 14:34:20 volumio volumio[3561]: info: sendMpdCommand playlistinfo took 7 milliseconds Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:34:20 volumio volumio[3561]: verbose: ControllerMpd::parseTrackInfo Apr 14 14:34:20 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:34:20 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:34:20 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":138187,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Zara Larsson - Memory Lane","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:34:20 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:34:20 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:20 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:34:20 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:34:20 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":138187,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Zara Larsson - Memory Lane","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:34:20 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:34:20 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:20 volumio volumio[3561]: info: ControllerMpd::pushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::servicePushState Apr 14 14:34:20 volumio volumio[3561]: info: CorePlayQueue::getTrack 0 Apr 14 14:34:20 volumio volumio[3561]: verbose: STATE SERVICE {"status":"play","position":0,"seek":138187,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Zara Larsson - Memory Lane","artist":"ANTENNE BAYERN","album":null,"uri":"http://stream.antenne.de:80/antenne","trackType":""} Apr 14 14:34:20 volumio volumio[3561]: verbose: CURRENT POSITION 0 Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::syncState stateService play Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::syncState currentStatus play Apr 14 14:34:20 volumio volumio[3561]: info: Received an update from plugin. extracting info from payload Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreStateMachine::pushState Apr 14 14:34:20 volumio volumio[3561]: info: CoreCommandRouter::volumioPushState Apr 14 14:34:20 volumio volumio[3561]: info: ------------------------------ 162ms Apr 14 14:34:20 volumio volumio[3561]: info: ------------------------------ 162ms Apr 14 14:34:20 volumio volumio[3561]: info: ------------------------------ 161ms Apr 14 14:34:20 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:20 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:20 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:20 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:20 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:20 volumio volumio[3561]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 14:34:21 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:34:21 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:34:21 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:34:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 108. Apr 14 14:34:21 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:34:21 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:34:21 volumio go-librespot[4323]: Librespot-go daemon starting... Apr 14 14:34:21 volumio go-librespot[4323]: time="2024-04-14T14:34:21+08:00" level=info msg="generated new device id: 8b0f9cc00be4cc41c614eff7f12fa409c2fbc40b" Apr 14 14:34:21 volumio go-librespot[4323]: time="2024-04-14T14:34:21+08:00" level=debug msg="stored credentials not found" Apr 14 14:34:22 volumio go-librespot[4323]: time="2024-04-14T14:34:22+08:00" level=debug msg="obtained new client token: AAAtdBs0lhC+1EJu5M6MhyVUwa08Iu0XJOuD5YxjMNZA27wfLho+TCC4mXxU2ejYXnsoH5qX5sfAFV7CyJ4heZFJL1nReNZS9dsNjXeUYrbZCOKZn06eZQ++tKFN/UU5XCkJ94zJSm1TfVeJmxLaxnTMe5nFarCvzKsCNlZAeeswPMLLgsJ9UoAg1P2EXngf6DGfcrGj190llwhZ+AwVYchjMoFfABlz91UJT+NTNmY2ZccBb9vALM8wxiHdLA==" Apr 14 14:34:22 volumio go-librespot[4323]: time="2024-04-14T14:34: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 14:34:22 volumio go-librespot[4323]: time="2024-04-14T14:34:22+08:00" level=debug msg="completed keyexchange" Apr 14 14:34:23 volumio go-librespot[4323]: time="2024-04-14T14:34:23+08:00" level=debug msg="completed challenge" Apr 14 14:34:23 volumio go-librespot[4323]: time="2024-04-14T14:34:23+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: TravelRestriction" Apr 14 14:34:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 14:34:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 14:34:24 volumio volumio[3561]: info: Initializing connection to go-librespot Websocket Apr 14 14:34:24 volumio volumio[3561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 14:34:26 volumio volumio[3561]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 14:34:26 volumio volumio[3561]: Error: connect ETIMEDOUT 199.59.149.230:80 Apr 14 14:34:26 volumio volumio[3561]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Apr 14 14:34:26 volumio volumio[3561]: errno: -110, Apr 14 14:34:26 volumio volumio[3561]: code: 'ETIMEDOUT', Apr 14 14:34:26 volumio volumio[3561]: syscall: 'connect', Apr 14 14:34:26 volumio volumio[3561]: address: '199.59.149.230', Apr 14 14:34:26 volumio volumio[3561]: port: 80 Apr 14 14:34:26 volumio volumio[3561]: } Apr 14 14:34:26 volumio volumio[3561]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 14:34:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 14:34:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 109. Apr 14 14:34:26 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 14:34:26 volumio systemd[1]: Started go-librespot Daemon. Apr 14 14:34:26 volumio go-librespot[4339]: Librespot-go daemon starting... Apr 14 14:34:26 volumio go-librespot[4339]: time="2024-04-14T14:34:26+08:00" level=info msg="generated new device id: 3b48bafe01b70043b3ae4ea58ae27769a915fb62" Apr 14 14:34:26 volumio go-librespot[4339]: time="2024-04-14T14:34:26+08:00" level=debug msg="stored credentials not found" Apr 14 14:34:27 volumio sudo[4347]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-14 14:33 Apr 14 14:34:27 volumio sudo[4347]: 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"