-- Logs begin at Tue 2024-10-08 23:46:56 CST, end at Wed 2024-10-09 00:07:25 CST. -- Oct 09 00:06:01 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:01 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:01 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Oct 09 00:06:01 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:01 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:01 my-player go-librespot[5985]: Librespot-go daemon starting... Oct 09 00:06:01 my-player go-librespot[5985]: time="2024-10-09T00:06:01+08:00" level=info msg="generated new device id: d44b72fcb3ff7a05ffc4cc295852389e920c9533" Oct 09 00:06:01 my-player go-librespot[5985]: time="2024-10-09T00:06:01+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:02 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:02 my-player go-librespot[5985]: time="2024-10-09T00:06:02+08:00" level=debug msg="new websocket client" Oct 09 00:06:02 my-player volumio[5632]: info: Connection to go-librespot Websocket established Oct 09 00:06:02 my-player go-librespot[5985]: time="2024-10-09T00:06:02+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]" Oct 09 00:06:02 my-player go-librespot[5985]: time="2024-10-09T00:06:02+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 09 00:06:02 my-player go-librespot[5985]: time="2024-10-09T00:06:02+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 09 00:06:02 my-player go-librespot[5985]: time="2024-10-09T00:06:02+08:00" level=debug msg="zeroconf server listening on port 41145" Oct 09 00:06:03 my-player go-librespot[5985]: time="2024-10-09T00:06:03+08:00" level=debug msg="obtained new client token: AADVvqNSswMR8DEvMxA9LoDJvq0RYHS7dp0C745ZoyT1jJsXEAGhpwbHaNH3ELKbdF8FCLAv2UaLpNYB2JYVNhxt1ykVrrmjkO0Y2puzw+qDzpI48Igc629FwK/4EBSQt9vBlCO6rVcKaOXaPMMrDx4Lrshsfxc3xulm+z13NZNodmLwJCuD19PAV3VZv1X6vQ4I77Z5KDljxbcp4jGrTYcrVhIG3vjbBKoZKCq8Pp3mwAJq/6ilDUWYGZh2LA==" Oct 09 00:06:03 my-player go-librespot[5985]: time="2024-10-09T00:06:03+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:06:03 my-player go-librespot[5985]: time="2024-10-09T00:06:03+08:00" level=debug msg="completed keyexchange" Oct 09 00:06:03 my-player volumiologrotate[792]: ls: cannot access '/var/log/samba/log.wb-MY': No such file or directory Oct 09 00:06:03 my-player volumiologrotate[792]: ls: cannot access 'PLAYER': No such file or directory Oct 09 00:06:04 my-player go-librespot[5985]: time="2024-10-09T00:06:04+08:00" level=debug msg="completed challenge" Oct 09 00:06:04 my-player go-librespot[5985]: time="2024-10-09T00:06:04+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" Oct 09 00:06:04 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:06:04 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:06:04 my-player volumio[5632]: info: Connection to go-librespot Websocket closed Oct 09 00:06:05 my-player volumio[5632]: info: Getting Spotify volume Oct 09 00:06:05 my-player volumio[5632]: (node:5632) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:05 my-player volumio[5632]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:06:05 my-player volumio[5632]: (node:5632) 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: 6) Oct 09 00:06:05 my-player volumio[5632]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:06:05 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:06:05 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:06:05 my-player volumio[5632]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:06:05 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:07 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:07 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:07 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:07 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Oct 09 00:06:07 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:07 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:07 my-player go-librespot[6041]: Librespot-go daemon starting... Oct 09 00:06:07 my-player go-librespot[6041]: time="2024-10-09T00:06:07+08:00" level=info msg="generated new device id: 80ee1cca0fdf4d124cdd8b72b1a7d7c59d7f2a00" Oct 09 00:06:07 my-player go-librespot[6041]: time="2024-10-09T00:06:07+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:08 my-player go-librespot[6041]: time="2024-10-09T00:06:08+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 09 00:06:08 my-player go-librespot[6041]: time="2024-10-09T00:06:08+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 09 00:06:08 my-player go-librespot[6041]: time="2024-10-09T00:06:08+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 09 00:06:08 my-player go-librespot[6041]: time="2024-10-09T00:06:08+08:00" level=debug msg="zeroconf server listening on port 37855" Oct 09 00:06:09 my-player go-librespot[6041]: time="2024-10-09T00:06:09+08:00" level=debug msg="obtained new client token: AADUt5IfUN1c21oCIhPwiI8u6nJ24cV0SiIUfKJQB+h3lI8kLA608fudkPzK4U5yIQlBdIIj1mpQ3JAMmdGxguZcN5FzEQObjJJ4SL/9d3b6NwJiM47YXYoCLq2/x7aanogF5Hjjcbd2MWXhCUGUUTYZfrxBXq7o8bGOAtVQAZTw7R3fyqEO7bmZP4cIsoDJOiusKfrQrLK+S3ygomunLsk69KobpiD9PuHYUFSR/9yaWQtuYv2YnQak+Ofi6NZJ" Oct 09 00:06:09 my-player go-librespot[6041]: time="2024-10-09T00:06:09+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:06:09 my-player go-librespot[6041]: time="2024-10-09T00:06:09+08:00" level=debug msg="completed keyexchange" Oct 09 00:06:09 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:09 my-player go-librespot[6041]: time="2024-10-09T00:06:09+08:00" level=debug msg="completed challenge" Oct 09 00:06:09 my-player go-librespot[6041]: time="2024-10-09T00:06:09+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Oct 09 00:06:09 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:06:09 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:06:10 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:10 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:11 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 09 00:06:11 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 09 00:06:11 my-player volumio[5632]: info: Discovery: Getting this device information Oct 09 00:06:11 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:06:11 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:06:11 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 09 00:06:13 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:13 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Oct 09 00:06:13 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:13 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:13 my-player go-librespot[6049]: Librespot-go daemon starting... Oct 09 00:06:13 my-player go-librespot[6049]: time="2024-10-09T00:06:13+08:00" level=info msg="generated new device id: df1e3fb934427b5e291bcc899e4c628dfee0216f" Oct 09 00:06:13 my-player go-librespot[6049]: time="2024-10-09T00:06:13+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:13 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:13 my-player go-librespot[6049]: time="2024-10-09T00:06:13+08:00" level=debug msg="new websocket client" Oct 09 00:06:13 my-player volumio[5632]: info: Connection to go-librespot Websocket established Oct 09 00:06:13 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:14 my-player go-librespot[6049]: time="2024-10-09T00:06:14+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]" Oct 09 00:06:14 my-player go-librespot[6049]: time="2024-10-09T00:06:14+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 09 00:06:14 my-player go-librespot[6049]: time="2024-10-09T00:06:14+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 09 00:06:14 my-player go-librespot[6049]: time="2024-10-09T00:06:14+08:00" level=debug msg="zeroconf server listening on port 40151" Oct 09 00:06:14 my-player volumio[5632]: info: CALLMETHOD: miscellanea my_music updateMusicLibraryBrowseSourcesVisibility [object Object] Oct 09 00:06:14 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: my_music , updateMusicLibraryBrowseSourcesVisibility Oct 09 00:06:14 my-player volumio[5632]: info: CoreCommandRouter::volumioUpdateToBrowseSources Oct 09 00:06:14 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 09 00:06:14 my-player volumio[5632]: Cannot find translation for source YouTube Music Oct 09 00:06:14 my-player volumio[5632]: Cannot find translation for source 80s80s Radio Oct 09 00:06:14 my-player volumio[5632]: Cannot find translation for source Mother Earth Radio Oct 09 00:06:14 my-player volumio[5632]: Cannot find translation for source Personal Radio Oct 09 00:06:14 my-player volumio[5632]: Cannot find translation for source Spotify Oct 09 00:06:14 my-player go-librespot[6049]: time="2024-10-09T00:06:14+08:00" level=debug msg="obtained new client token: AABcRzPxMU5ZcPPp0Emz0kgSTbpLdx2/OC6PrtXFDGVtzLvbZ/IFlIXX81KAjdGslkDElIkWDaveyL6zmqhKVJbvHCHwODppCx+yX/zGeX5EVV1+4BLoIf4NsjSngYFXIWX4KEfMjyWCNZvtFN3lk5ECuA9DiKWQBgUJZHwn6sFl0UVI7GkKDp1V7zILNMbxHGdywGnP640OhdIasBA71yhZfhljUeOh3BT8Y/VJlm6mQSpw/pKuse3MqUcz6RHZ" Oct 09 00:06:14 my-player go-librespot[6049]: time="2024-10-09T00:06:14+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:06:15 my-player go-librespot[6049]: time="2024-10-09T00:06:15+08:00" level=debug msg="completed keyexchange" Oct 09 00:06:15 my-player go-librespot[6049]: time="2024-10-09T00:06:15+08:00" level=debug msg="completed challenge" Oct 09 00:06:15 my-player go-librespot[6049]: time="2024-10-09T00:06:15+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" Oct 09 00:06:15 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:06:15 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:06:15 my-player volumio[5632]: info: Connection to go-librespot Websocket closed Oct 09 00:06:16 my-player volumio[5632]: info: Getting Spotify volume Oct 09 00:06:16 my-player volumio[5632]: (node:5632) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:16 my-player volumio[5632]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:06:16 my-player volumio[5632]: (node:5632) 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) Oct 09 00:06:16 my-player volumio[5632]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:06:16 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:06:16 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:06:16 my-player volumio[5632]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:06:17 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:18 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:18 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:18 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:18 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Oct 09 00:06:18 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:18 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:18 my-player go-librespot[6058]: Librespot-go daemon starting... Oct 09 00:06:18 my-player go-librespot[6058]: time="2024-10-09T00:06:18+08:00" level=info msg="generated new device id: 099eeba3f01e60ff7dd4e43779760836ce3818c6" Oct 09 00:06:18 my-player go-librespot[6058]: time="2024-10-09T00:06:18+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:19 my-player go-librespot[6058]: time="2024-10-09T00:06:19+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]" Oct 09 00:06:19 my-player go-librespot[6058]: time="2024-10-09T00:06:19+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 09 00:06:19 my-player go-librespot[6058]: time="2024-10-09T00:06:19+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 09 00:06:19 my-player go-librespot[6058]: time="2024-10-09T00:06:19+08:00" level=debug msg="zeroconf server listening on port 46103" Oct 09 00:06:20 my-player go-librespot[6058]: time="2024-10-09T00:06:20+08:00" level=debug msg="obtained new client token: AAB6mcEhhCKu9tytL/Sj3LFsV6U9ieigGsapZ98iKotZol9QtDcZrgeVNX6O0GFUqLvNQMtqIx5qsnJMuTzmq6Z3RtA4uFHv6wCgu4u1aSyn0q8SdHRC51mk9UgEYw5pGvzN6cDEk19bRnazl/cRmq4k4D5VEVimd6N7z6M/Mkt92DFlW+cM1Tn7h7CVkIm30RHGOHYllHa9eLLyJwKr4e0tV5Y8/VrYEqtcOfmrWOcGFJg2M+lyjo9ZTanNBBEF" Oct 09 00:06:20 my-player go-librespot[6058]: time="2024-10-09T00:06:20+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070 (error: dial tcp 104.199.241.202:4070: connect: connection refused), retrying with a different AP" Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::volumioGetBrowseSources Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::volumioGetBrowseSources Oct 09 00:06:20 my-player volumio[5632]: info: CoreCommandRouter::volumioGetBrowseSources Oct 09 00:06:21 my-player go-librespot[6058]: time="2024-10-09T00:06:21+08:00" level=info msg="connected to ap-gae2.spotify.com:443" Oct 09 00:06:21 my-player go-librespot[6058]: time="2024-10-09T00:06:21+08:00" level=debug msg="completed keyexchange" Oct 09 00:06:21 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:21 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Oct 09 00:06:21 my-player go-librespot[6058]: time="2024-10-09T00:06:21+08:00" level=debug msg="completed challenge" Oct 09 00:06:21 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:21 my-player go-librespot[6058]: time="2024-10-09T00:06:21+08:00" level=debug msg="new websocket client" Oct 09 00:06:21 my-player volumio[5632]: info: Connection to go-librespot Websocket established Oct 09 00:06:21 my-player go-librespot[6058]: time="2024-10-09T00:06:21+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" Oct 09 00:06:21 my-player volumio[5632]: info: Connection to go-librespot Websocket closed Oct 09 00:06:21 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:06:21 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:06:24 my-player volumio[5632]: info: Getting Spotify volume Oct 09 00:06:24 my-player volumio[5632]: (node:5632) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:24 my-player volumio[5632]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:06:24 my-player volumio[5632]: (node:5632) 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) Oct 09 00:06:24 my-player volumio[5632]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:06:24 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:06:24 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:06:24 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:24 my-player volumio[5632]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:06:24 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:24 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:24 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Oct 09 00:06:24 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:24 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:24 my-player go-librespot[6067]: Librespot-go daemon starting... Oct 09 00:06:24 my-player go-librespot[6067]: time="2024-10-09T00:06:24+08:00" level=info msg="generated new device id: 72d89dfbccbcbc14a2c6410c0b3a38207670d7b9" Oct 09 00:06:24 my-player go-librespot[6067]: time="2024-10-09T00:06:24+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:25 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:25 my-player go-librespot[6067]: time="2024-10-09T00:06:25+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]" Oct 09 00:06:25 my-player go-librespot[6067]: time="2024-10-09T00:06:25+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 09 00:06:25 my-player go-librespot[6067]: time="2024-10-09T00:06:25+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 09 00:06:25 my-player go-librespot[6067]: time="2024-10-09T00:06:25+08:00" level=debug msg="zeroconf server listening on port 36257" Oct 09 00:06:26 my-player go-librespot[6067]: time="2024-10-09T00:06:26+08:00" level=debug msg="obtained new client token: AADXxdnB5OVzb9l0PEtO5NAXYN1GaCg3jMcqe/bDbgZ/oj8kKcQbOtjMX0Qpdpzm2cq7ywxZsSeJVQTwOZsqK3f/vMh4+mcLngOfNL+hV49Qem2Q0RlyMcAPFBI44nogEit9Y/GMqt+GicrmGtd/dRdzs/O/ZnjZdn6SuW9Vo5Kn+fuKI68Ma+vpN+ig5QMcWxN/WSdi8dKFORAsUcu6r3hlYba2m5xE4Us/Jl2X3be9UvhyW0iW1sEWdV1d9tL9" Oct 09 00:06:26 my-player go-librespot[6067]: time="2024-10-09T00:06:26+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:06:26 my-player go-librespot[6067]: time="2024-10-09T00:06:26+08:00" level=debug msg="completed keyexchange" Oct 09 00:06:27 my-player go-librespot[6067]: time="2024-10-09T00:06:27+08:00" level=debug msg="completed challenge" Oct 09 00:06:27 my-player go-librespot[6067]: time="2024-10-09T00:06:27+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Oct 09 00:06:27 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:06:27 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:06:27 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:27 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:29 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:30 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:30 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Oct 09 00:06:30 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:30 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:30 my-player go-librespot[6075]: Librespot-go daemon starting... Oct 09 00:06:30 my-player go-librespot[6075]: time="2024-10-09T00:06:30+08:00" level=info msg="generated new device id: 8d4e29a13eb0445b372335c56170f126414fdb61" Oct 09 00:06:30 my-player go-librespot[6075]: time="2024-10-09T00:06:30+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:30 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:30 my-player go-librespot[6075]: time="2024-10-09T00:06:30+08:00" level=debug msg="new websocket client" Oct 09 00:06:30 my-player volumio[5632]: info: Connection to go-librespot Websocket established Oct 09 00:06:31 my-player go-librespot[6075]: time="2024-10-09T00:06:31+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]" Oct 09 00:06:31 my-player go-librespot[6075]: time="2024-10-09T00:06:31+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 09 00:06:31 my-player go-librespot[6075]: time="2024-10-09T00:06:31+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 09 00:06:31 my-player go-librespot[6075]: time="2024-10-09T00:06:31+08:00" level=debug msg="zeroconf server listening on port 33617" Oct 09 00:06:31 my-player go-librespot[6075]: time="2024-10-09T00:06:31+08:00" level=debug msg="obtained new client token: AACT6TI4rfR15GKEyZi3S9fUW76Y1PS2nMAXqnhW7sNJf89IJL009PqYkdxCSGlk/BrG+/T12kjq6uKDhuimRnKJnxb6PQqsW1N52HcLG9/dgzBotRnh6Nwva4bvMTY/QJ4r8w76j2A/+RS6gqrYguyzt/KKceDG1IxfLYzIwyiRp9ZGE2xANcXEpH3zpBZ34DB6UPAAjE23Jyh3kAdj38yoROFs5P4QX07qLMOI6kSCeysEuFZFLfroEMFPxjFs" Oct 09 00:06:32 my-player go-librespot[6075]: time="2024-10-09T00:06:32+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:06:32 my-player go-librespot[6075]: time="2024-10-09T00:06:32+08:00" level=debug msg="completed keyexchange" Oct 09 00:06:32 my-player go-librespot[6075]: time="2024-10-09T00:06:32+08:00" level=debug msg="completed challenge" Oct 09 00:06:32 my-player go-librespot[6075]: time="2024-10-09T00:06:32+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" Oct 09 00:06:32 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:06:32 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:06:32 my-player volumio[5632]: info: Connection to go-librespot Websocket closed Oct 09 00:06:33 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:33 my-player volumio[5632]: info: Getting Spotify volume Oct 09 00:06:33 my-player volumio[5632]: (node:5632) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:33 my-player volumio[5632]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:06:33 my-player volumio[5632]: (node:5632) 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) Oct 09 00:06:33 my-player volumio[5632]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:06:33 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:06:33 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:06:33 my-player volumio[5632]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:06:35 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:35 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:35 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:35 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Oct 09 00:06:35 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:35 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:35 my-player go-librespot[6083]: Librespot-go daemon starting... Oct 09 00:06:35 my-player go-librespot[6083]: time="2024-10-09T00:06:35+08:00" level=info msg="generated new device id: 50701a2e93c30d76f83ebebde6e3fa69391a2773" Oct 09 00:06:35 my-player go-librespot[6083]: time="2024-10-09T00:06:35+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:36 my-player go-librespot[6083]: time="2024-10-09T00:06:36+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]" Oct 09 00:06:36 my-player go-librespot[6083]: time="2024-10-09T00:06:36+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 09 00:06:36 my-player go-librespot[6083]: time="2024-10-09T00:06:36+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 09 00:06:36 my-player go-librespot[6083]: time="2024-10-09T00:06:36+08:00" level=debug msg="zeroconf server listening on port 40221" Oct 09 00:06:37 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:37 my-player go-librespot[6083]: time="2024-10-09T00:06:37+08:00" level=debug msg="obtained new client token: AADVjXzI8Pk7gSSyIqMj80HOTyOkxQoArR/jFdUxqQiUGQrdiMhFCxfJI39cPns1ufPHXwUn15FElMieRo4QbLu6/dg1iQbVs3czu118yJkjex8/OG9OoMBxeqligPIkss64Ge+8ftlU6PK7Hb864tv//a9oo5gkqgD0SmKqZi6RZ7fH6WRX3kAAeTpH/aMz9zJbMmVyug/bv4vhGmIOjeZ4VrMr4tuL3pxYPEc/Jlphq2YCC713jxqlLksbqKji" Oct 09 00:06:37 my-player go-librespot[6083]: time="2024-10-09T00:06:37+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:06:37 my-player go-librespot[6083]: time="2024-10-09T00:06:37+08:00" level=debug msg="completed keyexchange" Oct 09 00:06:38 my-player go-librespot[6083]: time="2024-10-09T00:06:38+08:00" level=debug msg="completed challenge" Oct 09 00:06:38 my-player go-librespot[6083]: time="2024-10-09T00:06: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" Oct 09 00:06:38 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:06:38 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:06:38 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:38 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:41 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:41 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 09 00:06:41 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 09 00:06:41 my-player volumio[5632]: info: Discovery: Getting this device information Oct 09 00:06:41 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:06:41 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:06:41 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 09 00:06:41 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:41 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Oct 09 00:06:41 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:41 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:41 my-player go-librespot[6092]: Librespot-go daemon starting... Oct 09 00:06:41 my-player go-librespot[6092]: time="2024-10-09T00:06:41+08:00" level=info msg="generated new device id: ecc996b96728339194cb87fa939f6bf1508d8f5a" Oct 09 00:06:41 my-player go-librespot[6092]: time="2024-10-09T00:06:41+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:41 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:41 my-player go-librespot[6092]: time="2024-10-09T00:06:41+08:00" level=debug msg="new websocket client" Oct 09 00:06:41 my-player volumio[5632]: info: Connection to go-librespot Websocket established Oct 09 00:06:42 my-player go-librespot[6092]: time="2024-10-09T00:06: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-gew1.spotify.com:80]" Oct 09 00:06:42 my-player go-librespot[6092]: time="2024-10-09T00:06:42+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 09 00:06:42 my-player go-librespot[6092]: time="2024-10-09T00:06:42+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 09 00:06:42 my-player go-librespot[6092]: time="2024-10-09T00:06:42+08:00" level=debug msg="zeroconf server listening on port 41583" Oct 09 00:06:43 my-player go-librespot[6092]: time="2024-10-09T00:06:43+08:00" level=debug msg="obtained new client token: AAC/egFRe4R8KIS/fe2YKIsi0Z9BXGDYlSNybOLQeYJ/WqHPc8jP1wj43UAcRMKJQJWt/moqIjpebwSlsBM369GRy2XKoq+cJqZRsMHPYA2lwZvVv/Z0mHlggAEWi2RRW40kQtI21Af9QTE4P1QVTE0MjVXO7zoe9r5S+m52L3c9nmeFprxxzxqKOG0GvZIiZrwBPUTT6EIMp4WWGyoPFElBzbzrmJ/2jXAy2XUl2Jpb80jIGLoS96hJQTuw0B6W" Oct 09 00:06:43 my-player go-librespot[6092]: time="2024-10-09T00:06:43+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:06:43 my-player go-librespot[6092]: time="2024-10-09T00:06:43+08:00" level=debug msg="completed keyexchange" Oct 09 00:06:44 my-player go-librespot[6092]: time="2024-10-09T00:06:44+08:00" level=debug msg="completed challenge" Oct 09 00:06:44 my-player go-librespot[6092]: time="2024-10-09T00:06:44+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" Oct 09 00:06:44 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:06:44 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:06:44 my-player volumio[5632]: info: Connection to go-librespot Websocket closed Oct 09 00:06:44 my-player volumio[5632]: info: Getting Spotify volume Oct 09 00:06:44 my-player volumio[5632]: (node:5632) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:44 my-player volumio[5632]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:06:44 my-player volumio[5632]: (node:5632) 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) Oct 09 00:06:44 my-player volumio[5632]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:06:44 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:06:44 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:06:44 my-player volumio[5632]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:06:45 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:47 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:47 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:47 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:47 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Oct 09 00:06:47 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:47 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:47 my-player go-librespot[6101]: Librespot-go daemon starting... Oct 09 00:06:47 my-player go-librespot[6101]: time="2024-10-09T00:06:47+08:00" level=info msg="generated new device id: ff3e4ad4641f3e299a942f733167232dda4b519a" Oct 09 00:06:47 my-player go-librespot[6101]: time="2024-10-09T00:06:47+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:48 my-player go-librespot[6101]: time="2024-10-09T00:06: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-gew4.spotify.com:80]" Oct 09 00:06:48 my-player go-librespot[6101]: time="2024-10-09T00:06:48+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 09 00:06:48 my-player go-librespot[6101]: time="2024-10-09T00:06:48+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 09 00:06:48 my-player go-librespot[6101]: time="2024-10-09T00:06:48+08:00" level=debug msg="zeroconf server listening on port 34467" Oct 09 00:06:49 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:49 my-player go-librespot[6101]: time="2024-10-09T00:06:49+08:00" level=debug msg="obtained new client token: AADpA/4cOsSBsHex5krwE6SWOuCHe3f7ATk6J2b7hxCsAbWNMqb+p6LEiKNi42qH80cYfQoro0Tkm3VIivDCyvVg2jDKtalaHwrCYwLusqrdup0zcPddioR1kIvdP2BX+SWL5jVlBjoJdM/lm2uM9pWYdYfn5bmJsxIrshJuxa+9OWz+rLmA/2HdfB74P8nXK9scn+Cqi8ORXSH5mg7BSjBtRuUuCMV68AT/qlP7V3tsVdrBHVYQtGaBcjqVxQ==" Oct 09 00:06:49 my-player go-librespot[6101]: time="2024-10-09T00:06:49+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:06:49 my-player go-librespot[6101]: time="2024-10-09T00:06:49+08:00" level=debug msg="completed keyexchange" Oct 09 00:06:50 my-player go-librespot[6101]: time="2024-10-09T00:06:50+08:00" level=debug msg="completed challenge" Oct 09 00:06:50 my-player go-librespot[6101]: time="2024-10-09T00:06:50+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" Oct 09 00:06:50 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:06:50 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:06:50 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:50 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:53 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:53 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:53 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Oct 09 00:06:53 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:53 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:53 my-player go-librespot[6110]: Librespot-go daemon starting... Oct 09 00:06:53 my-player go-librespot[6110]: time="2024-10-09T00:06:53+08:00" level=info msg="generated new device id: 2f99b6e32e251dbca4eacea5168b7056cbfbde0f" Oct 09 00:06:53 my-player go-librespot[6110]: time="2024-10-09T00:06:53+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:53 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:53 my-player go-librespot[6110]: time="2024-10-09T00:06:53+08:00" level=debug msg="new websocket client" Oct 09 00:06:53 my-player volumio[5632]: info: Connection to go-librespot Websocket established Oct 09 00:06:54 my-player go-librespot[6110]: time="2024-10-09T00:06:54+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]" Oct 09 00:06:54 my-player go-librespot[6110]: time="2024-10-09T00:06:54+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 09 00:06:54 my-player go-librespot[6110]: time="2024-10-09T00:06:54+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 09 00:06:54 my-player go-librespot[6110]: time="2024-10-09T00:06:54+08:00" level=debug msg="zeroconf server listening on port 35647" Oct 09 00:06:54 my-player volumio[5632]: info: CALLMETHOD: music_service mpd saveMusicLibraryOptions [object Object] Oct 09 00:06:54 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , saveMusicLibraryOptions Oct 09 00:06:54 my-player go-librespot[6110]: time="2024-10-09T00:06:54+08:00" level=debug msg="obtained new client token: AACwKP13hfuZSouQVCkYVQ66Z78a3B4t24x+2Sbq9lQdSpTA+l4Hg4I8FnL788eZvEfImc/8soo3Er/IiIewv1zd1qiXY9dSBd/muaSVYSfIFx2lOsg4IRjQFJ74Hu9Gs/uBpnsWJ6aMVYChNRWk35lO7NzaZss/x4k720aa1Grzxyj5bjEkxiVRNxBkfHZ9wllk7glffkfQn+nWqDi0XRlo5VzkMajC46Mj1lCV1IAgNrvV4Ayh5X/EsAxzJJct" Oct 09 00:06:55 my-player go-librespot[6110]: time="2024-10-09T00:06:55+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:06:55 my-player go-librespot[6110]: time="2024-10-09T00:06:55+08:00" level=debug msg="completed keyexchange" Oct 09 00:06:55 my-player go-librespot[6110]: time="2024-10-09T00:06:55+08:00" level=debug msg="completed challenge" Oct 09 00:06:55 my-player go-librespot[6110]: time="2024-10-09T00:06:55+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" Oct 09 00:06:55 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:06:55 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:06:55 my-player volumio[5632]: info: Connection to go-librespot Websocket closed Oct 09 00:06:56 my-player volumio[5632]: info: Getting Spotify volume Oct 09 00:06:56 my-player volumio[5632]: (node:5632) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:56 my-player volumio[5632]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:06:56 my-player volumio[5632]: (node:5632) 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) Oct 09 00:06:56 my-player volumio[5632]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:06:56 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:06:56 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:06:56 my-player volumio[5632]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:06:57 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:06:58 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:06:58 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:06:58 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:06:58 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Oct 09 00:06:58 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:06:58 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:06:58 my-player go-librespot[6119]: Librespot-go daemon starting... Oct 09 00:06:58 my-player go-librespot[6119]: time="2024-10-09T00:06:58+08:00" level=info msg="generated new device id: 067b204b6ae1c0d290659c9a2d1ab66725123cc4" Oct 09 00:06:58 my-player go-librespot[6119]: time="2024-10-09T00:06:58+08:00" level=debug msg="stored credentials not found" Oct 09 00:06:59 my-player go-librespot[6119]: time="2024-10-09T00:06: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-gew4.spotify.com:80]" Oct 09 00:06:59 my-player go-librespot[6119]: time="2024-10-09T00:06:59+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 09 00:06:59 my-player go-librespot[6119]: time="2024-10-09T00:06:59+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 09 00:06:59 my-player go-librespot[6119]: time="2024-10-09T00:06:59+08:00" level=debug msg="zeroconf server listening on port 43651" Oct 09 00:07:01 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:07:01 my-player go-librespot[6119]: time="2024-10-09T00:07:01+08:00" level=debug msg="obtained new client token: AACIVAkoi0tQ0cRbHvy+6x2NMIy4L0PiKmpa5x1SozoxcCD0pJ0wXc1vbKGsfQkvbFsKfj+i8PxT8lIraeKCYzLKuq1upCat8wfyrMP1pb/a6Gv8fwed1VVei6dnnapnBndyUshpCoKHdNl67jvn53VIa6Fldg7idwNTlJWXl120+HKcYbrqn0ENK50gIpff7DD+6UYzR36MqhAMqN1h2Peq5Bh73aQh4liEiktfG/5SUe4aKtuFS163HdnDRQ==" Oct 09 00:07:01 my-player go-librespot[6119]: time="2024-10-09T00:07:01+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:07:01 my-player go-librespot[6119]: time="2024-10-09T00:07:01+08:00" level=debug msg="completed keyexchange" Oct 09 00:07:01 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:07:01 my-player go-librespot[6119]: time="2024-10-09T00:07:01+08:00" level=debug msg="new websocket client" Oct 09 00:07:01 my-player volumio[5632]: info: Connection to go-librespot Websocket established Oct 09 00:07:02 my-player go-librespot[6119]: time="2024-10-09T00:07:02+08:00" level=debug msg="completed challenge" Oct 09 00:07:02 my-player go-librespot[6119]: time="2024-10-09T00:07:02+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" Oct 09 00:07:02 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:07:02 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:07:02 my-player volumio[5632]: info: Connection to go-librespot Websocket closed Oct 09 00:07:03 my-player volumiologrotate[792]: ls: cannot access '/var/log/samba/log.wb-MY': No such file or directory Oct 09 00:07:03 my-player volumiologrotate[792]: ls: cannot access 'PLAYER': No such file or directory Oct 09 00:07:04 my-player volumio[5632]: info: Getting Spotify volume Oct 09 00:07:04 my-player volumio[5632]: (node:5632) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:07:04 my-player volumio[5632]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:07:04 my-player volumio[5632]: (node:5632) 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) Oct 09 00:07:04 my-player volumio[5632]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:07:04 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:07:04 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:07:04 my-player volumio[5632]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:07:05 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:07:05 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:07:05 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:07:05 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:07:05 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Oct 09 00:07:05 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:07:05 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:07:05 my-player go-librespot[6175]: Librespot-go daemon starting... Oct 09 00:07:05 my-player go-librespot[6175]: time="2024-10-09T00:07:05+08:00" level=info msg="generated new device id: ddc9c5e35e593773fbc320d7616024d8aa2593ab" Oct 09 00:07:05 my-player go-librespot[6175]: time="2024-10-09T00:07:05+08:00" level=debug msg="stored credentials not found" Oct 09 00:07:06 my-player go-librespot[6175]: time="2024-10-09T00:07:06+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]" Oct 09 00:07:06 my-player go-librespot[6175]: time="2024-10-09T00:07:06+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 09 00:07:06 my-player go-librespot[6175]: time="2024-10-09T00:07:06+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 09 00:07:06 my-player go-librespot[6175]: time="2024-10-09T00:07:06+08:00" level=debug msg="zeroconf server listening on port 46389" Oct 09 00:07:06 my-player go-librespot[6175]: time="2024-10-09T00:07:06+08:00" level=debug msg="obtained new client token: AABEW8RTD0iQtuGhet5hfSV+SEtgupChNu1wes+FTyDryHzD8tJy4NELVtwWYhx/Z14zDSJvipP/MNFTwGAN7tDl63tCFGNSww8fBOx1/wmXx9wlaeRzu6LfFKevuKgYVz0D85fWX539Laz04DENn+SZBaernY74AaudUrlY/c2Xi/oydIbkPYemzgSQbSCUq5Y5sMk6a0NaCPZxlYVynTSiVmcx1jCLECkhPgwn5oPabr//6ovSn+E16ZOE/7Nq" Oct 09 00:07:07 my-player go-librespot[6175]: time="2024-10-09T00:07:07+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:07:07 my-player go-librespot[6175]: time="2024-10-09T00:07:07+08:00" level=debug msg="completed keyexchange" Oct 09 00:07:07 my-player go-librespot[6175]: time="2024-10-09T00:07:07+08:00" level=debug msg="completed challenge" Oct 09 00:07:07 my-player go-librespot[6175]: time="2024-10-09T00:07:07+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" Oct 09 00:07:07 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:07:07 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:07:08 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:07:08 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:07:09 my-player volumio[5632]: info: CoreCommandRouter::volumioPlay Oct 09 00:07:09 my-player volumio[5632]: info: CoreStateMachine::play index undefined Oct 09 00:07:09 my-player volumio[5632]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 09 00:07:09 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:07:09 my-player volumio[5632]: info: CoreStateMachine::startPlaybackTimer Oct 09 00:07:09 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:07:09 my-player volumio[5632]: verbose: ControllerMpd::clearAddPlayTracks USB/DATA/Music/琴歌-关山月/关山月Moon on Guan Mountain.flac Oct 09 00:07:09 my-player volumio[5632]: verbose: ControllerMpd::sendMpdCommand stop Oct 09 00:07:09 my-player volumio[5632]: info: sendMpdCommand stop took 2 milliseconds Oct 09 00:07:09 my-player volumio[5632]: verbose: ControllerMpd::sendMpdCommand clear Oct 09 00:07:09 my-player volumio[5632]: info: Oct 09 00:07:09 my-player volumio[5632]: ---------------------------- MPD announces system playlist update Oct 09 00:07:09 my-player volumio[5632]: info: Ignoring MPD Status Update Oct 09 00:07:09 my-player volumio[5632]: info: sendMpdCommand clear took 2 milliseconds Oct 09 00:07:09 my-player volumio[5632]: verbose: ControllerMpd::sendMpdCommand add "USB/DATA/Music/琴歌-关山月/关山月Moon on Guan Mountain.flac" Oct 09 00:07:09 my-player volumio[5632]: info: Oct 09 00:07:09 my-player volumio[5632]: ---------------------------- MPD announces system playlist update Oct 09 00:07:09 my-player volumio[5632]: info: Ignoring MPD Status Update Oct 09 00:07:09 my-player volumio[5632]: info: Oct 09 00:07:09 my-player volumio[5632]: ---------------------------- MPD announces system playlist update Oct 09 00:07:09 my-player volumio[5632]: info: Ignoring MPD Status Update Oct 09 00:07:09 my-player volumio[5632]: error: updateQueue error: null Oct 09 00:07:09 my-player volumio[5632]: error: updateQueue error: null Oct 09 00:07:09 my-player volumio[5632]: error: updateQueue error: null Oct 09 00:07:09 my-player volumio[5632]: info: ------------------------------ 13ms Oct 09 00:07:09 my-player volumio[5632]: info: ------------------------------ 9ms Oct 09 00:07:09 my-player volumio[5632]: info: ------------------------------ 7ms Oct 09 00:07:10 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:07:10 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Oct 09 00:07:10 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:07:10 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:07:10 my-player go-librespot[6184]: Librespot-go daemon starting... Oct 09 00:07:10 my-player go-librespot[6184]: time="2024-10-09T00:07:10+08:00" level=info msg="generated new device id: 636f4143df2d0d73b9900a6d9b1d18930b257fc7" Oct 09 00:07:10 my-player go-librespot[6184]: time="2024-10-09T00:07:10+08:00" level=debug msg="stored credentials not found" Oct 09 00:07:11 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:07:11 my-player go-librespot[6184]: time="2024-10-09T00:07:11+08:00" level=debug msg="new websocket client" Oct 09 00:07:11 my-player volumio[5632]: info: Connection to go-librespot Websocket established Oct 09 00:07:11 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 09 00:07:11 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 09 00:07:11 my-player volumio[5632]: info: Discovery: Getting this device information Oct 09 00:07:11 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:07:11 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:07:11 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 09 00:07:11 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 09 00:07:11 my-player volumio[5632]: info: CURURI: music-library Oct 09 00:07:11 my-player volumio[5632]: error: Failed LSINFO: null Oct 09 00:07:11 my-player volumio[5632]: info: Preload queue cleared Oct 09 00:07:12 my-player go-librespot[6184]: time="2024-10-09T00:07:12+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]" Oct 09 00:07:12 my-player go-librespot[6184]: time="2024-10-09T00:07:12+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 09 00:07:12 my-player go-librespot[6184]: time="2024-10-09T00:07:12+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 09 00:07:12 my-player go-librespot[6184]: time="2024-10-09T00:07:12+08:00" level=debug msg="zeroconf server listening on port 43091" Oct 09 00:07:13 my-player go-librespot[6184]: time="2024-10-09T00:07:13+08:00" level=debug msg="obtained new client token: AADf25UDEIjKjkxgFh8Zb4iUhdpygDkkxf1+d5vxlRDMHGQwT2COjWnpEfgHb0bCM5u+A3fMtskiGmyHD90+TYHFKo+Ebu1I9iFEo2CG9kT3jSChrj930P7T8eSXCSwcILlEdTx9JvSS/8UKKNWrn4b5TM9hOAMVeIAX/qp2hLHr6F4TpdmYccO0qck9n3NSGx6T5Ujiy2caeenpZ2fjRz5jYoiNMtluNCWRQqQlXo398XlW8Cu0+5uYGpgoe4dw" Oct 09 00:07:13 my-player go-librespot[6184]: time="2024-10-09T00:07:13+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:07:13 my-player go-librespot[6184]: time="2024-10-09T00:07:13+08:00" level=debug msg="completed keyexchange" Oct 09 00:07:14 my-player go-librespot[6184]: time="2024-10-09T00:07:14+08:00" level=debug msg="completed challenge" Oct 09 00:07:14 my-player go-librespot[6184]: time="2024-10-09T00:07:14+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Oct 09 00:07:14 my-player volumio[5632]: info: Getting Spotify volume Oct 09 00:07:14 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:07:14 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:07:14 my-player volumio[5632]: (node:5632) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:07:14 my-player volumio[5632]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:07:14 my-player volumio[5632]: (node:5632) 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: 13) Oct 09 00:07:14 my-player volumio[5632]: info: Connection to go-librespot Websocket closed Oct 09 00:07:14 my-player volumio[5632]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:07:14 my-player volumio[5632]: info: CoreCommandRouter::volumioGetState Oct 09 00:07:14 my-player volumio[5632]: info: CorePlayQueue::getTrack 0 Oct 09 00:07:14 my-player volumio[5632]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:07:17 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:07:17 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:07:17 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:07:17 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Oct 09 00:07:17 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:07:17 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:07:17 my-player go-librespot[6192]: Librespot-go daemon starting... Oct 09 00:07:17 my-player go-librespot[6192]: time="2024-10-09T00:07:17+08:00" level=info msg="generated new device id: 9596a569e94e0510161ceb9bffcbbd74d24e6662" Oct 09 00:07:17 my-player go-librespot[6192]: time="2024-10-09T00:07:17+08:00" level=debug msg="stored credentials not found" Oct 09 00:07:18 my-player go-librespot[6192]: time="2024-10-09T00:07:18+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 09 00:07:18 my-player go-librespot[6192]: time="2024-10-09T00:07:18+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 09 00:07:18 my-player go-librespot[6192]: time="2024-10-09T00:07:18+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 09 00:07:18 my-player go-librespot[6192]: time="2024-10-09T00:07:18+08:00" level=debug msg="zeroconf server listening on port 35653" Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::volumioGetBrowseSources Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::volumioGetBrowseSources Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::volumioGetBrowseSources Oct 09 00:07:19 my-player go-librespot[6192]: time="2024-10-09T00:07:19+08:00" level=debug msg="obtained new client token: AACadsdhzdwejgms+YOvZzgglo4xSZlBuCbwxMqS/D26oRUZswN1Qq53GxSrtvEaQ8rnePw4VXb9LlhiE5p8AXNzGemSwewoUtfRtylJwAxpTuUZxxxJ3GCIe35B+VmW2XHLcgviNGcTOAxmIwRMgJ/YJjiYpDtuVkx8zomoaEMrdzuaXNdhnNtor+zCjWbds60uho/lnWRGWYP52khrFxWwKbYcMU2a8iEcIJuwrjDGhOGkJGh4s4O2f8Ybug==" Oct 09 00:07:19 my-player go-librespot[6192]: time="2024-10-09T00:07:19+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:07:19 my-player go-librespot[6192]: time="2024-10-09T00:07:19+08:00" level=debug msg="completed keyexchange" Oct 09 00:07:19 my-player volumio[5632]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Oct 09 00:07:19 my-player go-librespot[6192]: time="2024-10-09T00:07:19+08:00" level=debug msg="completed challenge" Oct 09 00:07:20 my-player go-librespot[6192]: time="2024-10-09T00:07:20+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" Oct 09 00:07:20 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:07:20 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:07:20 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:07:20 my-player volumio[5632]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:07:23 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:07:23 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Oct 09 00:07:23 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:07:23 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:07:23 my-player go-librespot[6200]: Librespot-go daemon starting... Oct 09 00:07:23 my-player go-librespot[6200]: time="2024-10-09T00:07:23+08:00" level=info msg="generated new device id: 16c2a75e5b50aae25d84601359452bf91728efec" Oct 09 00:07:23 my-player go-librespot[6200]: time="2024-10-09T00:07:23+08:00" level=debug msg="stored credentials not found" Oct 09 00:07:23 my-player volumio[5632]: info: Initializing connection to go-librespot Websocket Oct 09 00:07:23 my-player go-librespot[6200]: time="2024-10-09T00:07:23+08:00" level=debug msg="new websocket client" Oct 09 00:07:23 my-player volumio[5632]: info: Connection to go-librespot Websocket established Oct 09 00:07:23 my-player go-librespot[6200]: time="2024-10-09T00:07:23+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 09 00:07:23 my-player go-librespot[6200]: time="2024-10-09T00:07:23+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 09 00:07:23 my-player go-librespot[6200]: time="2024-10-09T00:07:23+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 09 00:07:23 my-player go-librespot[6200]: time="2024-10-09T00:07:23+08:00" level=debug msg="zeroconf server listening on port 39799" Oct 09 00:07:24 my-player nmbd[1053]: [2024/10/09 00:07:24.365524, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Oct 09 00:07:24 my-player nmbd[1053]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.0.20 for name WORKGROUP<1d>. Oct 09 00:07:24 my-player nmbd[1053]: This response was from IP 192.168.0.2, reporting an IP address of 192.168.0.2. Oct 09 00:07:24 my-player go-librespot[6200]: time="2024-10-09T00:07:24+08:00" level=debug msg="obtained new client token: AABF6+Wz1ZIwGBjp58cC/I3oETnlss/4fPllnqT1foVNBDRzpzFouy2GP8I88sJjLdSDnhlffRJzxY0G7zAqpR4S1EI5hwqvnWEBcjLybE7jQoSDafEbP0Ux9HVpQp6gj3NZKqqdzKaolsmJCvRbSblzxjlKkdO6ZI3z9kGkvkxW/aCuDt9uVhBU+dRKrj6gvP0+QfSMYzL7gRLCo2Vn2khjmWEaEL1Tuv6jjZJRMIO5ct2G8fL/KHPY6LfTfCmU" Oct 09 00:07:24 my-player go-librespot[6200]: time="2024-10-09T00:07:24+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:07:24 my-player go-librespot[6200]: time="2024-10-09T00:07:24+08:00" level=debug msg="completed keyexchange" Oct 09 00:07:25 my-player volumio[5632]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 09 00:07:25 my-player volumio[5632]: Error: connect ETIMEDOUT 199.59.149.136:80 Oct 09 00:07:25 my-player volumio[5632]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Oct 09 00:07:25 my-player volumio[5632]: errno: -110, Oct 09 00:07:25 my-player volumio[5632]: code: 'ETIMEDOUT', Oct 09 00:07:25 my-player volumio[5632]: syscall: 'connect', Oct 09 00:07:25 my-player volumio[5632]: address: '199.59.149.136', Oct 09 00:07:25 my-player volumio[5632]: port: 80 Oct 09 00:07:25 my-player volumio[5632]: } Oct 09 00:07:25 my-player volumio[5632]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 09 00:07:25 my-player go-librespot[6200]: time="2024-10-09T00:07:25+08:00" level=debug msg="completed challenge" Oct 09 00:07:25 my-player go-librespot[6200]: time="2024-10-09T00:07:25+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" Oct 09 00:07:25 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:07:25 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:07:25 my-player sudo[6218]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-09 00:06 Oct 09 00:07:25 my-player sudo[6218]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:33:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ee834e1c2a28de3c5d8c48611ecf1167"