-- Logs begin at Sun 2024-04-14 14:23:07 CST, end at Sun 2024-04-14 15:03:23 CST. -- Apr 14 15:02:00 volumio volumio[10084]: SPOTIFY: User informations: {"display_name":"邱瑞华","external_urls":{"spotify":"https://open.spotify.com/user/31dd2kulom3iljqxj6iee4jqblee"},"href":"https://api.spotify.com/v1/users/31dd2kulom3iljqxj6iee4jqblee","id":"31dd2kulom3iljqxj6iee4jqblee","images":[],"type":"user","uri":"spotify:user:31dd2kulom3iljqxj6iee4jqblee","followers":{"href":null,"total":0},"country":"US","product":"free","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"466223606@qq.com"} Apr 14 15:02:00 volumio volumio[10084]: info: Spotify Successfully logged in Apr 14 15:02:00 volumio volumio[10084]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:02:00 volumio volumio[10084]: info: [1713078120072] CoreMusicLibrary::Adding element Spotify Apr 14 15:02:00 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:02:00 volumio volumio[10084]: Cannot find translation for source 80s80s Radio Apr 14 15:02:00 volumio volumio[10084]: Cannot find translation for source Podcast Apr 14 15:02:00 volumio volumio[10084]: Cannot find translation for source Spotify Apr 14 15:02:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 370. Apr 14 15:02:01 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:01 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:01 volumio go-librespot[10448]: Librespot-go daemon starting... Apr 14 15:02:01 volumio go-librespot[10448]: time="2024-04-14T15:02:01+08:00" level=info msg="generated new device id: 2149e20ab136a5331ec69290d5db320ea79358e8" Apr 14 15:02:01 volumio go-librespot[10448]: time="2024-04-14T15:02:01+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:01 volumio go-librespot[10448]: time="2024-04-14T15:02:01+08:00" level=debug msg="obtained new client token: AABeKEHmETCtcgoCVHQTlvjfGVSWmG42CZvMlwv9EimSLSZYpV31gXhEM9c+Z+QkGuxuAhBHqieke0lAVznycx4vWQSKo13as2ncq+nnrOdoikgkhfr3WXds5/kIa0KAysI0ChXqNMPSToFClEuWZXhOYzat8o1rhK5q1evy8b1pCRlENF7+rjl8QhG4+jWEl8+ZhHyQN2pXRuCHeCein6IUFpvxq1XX7MgpalkVo6Z+hijE+fDW6uTbNLkzSHyo" Apr 14 15:02:01 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:01 volumio go-librespot[10448]: time="2024-04-14T15:02:01+08:00" level=debug msg="new websocket client" Apr 14 15:02:01 volumio volumio[10084]: info: Connection to go-librespot Websocket established Apr 14 15:02:02 volumio go-librespot[10448]: time="2024-04-14T15:02: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:02:02 volumio go-librespot[10448]: time="2024-04-14T15:02:02+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:02 volumio go-librespot[10448]: time="2024-04-14T15:02:02+08:00" level=debug msg="completed challenge" Apr 14 15:02:03 volumio go-librespot[10448]: time="2024-04-14T15:02:03+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 15:02:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:03 volumio volumio[10084]: info: Connection to go-librespot Websocket closed Apr 14 15:02:04 volumio volumio[10084]: info: AutoStart - Plugin is starting Apr 14 15:02:04 volumio volumio[10084]: info: CoreCommandRouter::volumioGetQueue Apr 14 15:02:04 volumio volumio[10084]: info: CoreStateMachine::getQueue Apr 14 15:02:04 volumio volumio[10084]: info: CorePlayQueue::getQueue Apr 14 15:02:04 volumio volumio[10084]: info: Getting Spotify volume Apr 14 15:02:04 volumio volumio[10084]: (node:10084) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:04 volumio volumio[10084]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 15:02:04 volumio volumio[10084]: (Use `node --trace-warnings ...` to show where the warning was created) Apr 14 15:02:04 volumio volumio[10084]: (node:10084) 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: 1) Apr 14 15:02:04 volumio volumio[10084]: (node:10084) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. Apr 14 15:02:04 volumio volumio[10084]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 15:02:04 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:02:04 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:04 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:04 volumio volumio[10084]: SPOTIFY: SPOTIFY VOLUME undefined Apr 14 15:02:04 volumio volumio[10084]: SPOTIFY: VOLUMIO VOLUME 69 Apr 14 15:02:04 volumio volumio[10084]: info: Aligning Spotify Volume to Volumio Volume Apr 14 15:02:04 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:02:04 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:04 volumio volumio[10084]: info: Setting Spotify Volume from Volumio: 69 Apr 14 15:02:06 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:06 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 371. Apr 14 15:02:06 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:06 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:06 volumio go-librespot[10457]: Librespot-go daemon starting... Apr 14 15:02:06 volumio go-librespot[10457]: time="2024-04-14T15:02:06+08:00" level=info msg="generated new device id: e9ca5561b81547ffe3f265d3fcf5c3aab361b9be" Apr 14 15:02:06 volumio go-librespot[10457]: time="2024-04-14T15:02:06+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:06 volumio volumio[10084]: SPOTIFY: SETTING SPOTIFY VOLUME 69 Apr 14 15:02:06 volumio volumio[10084]: info: Sending Spotify command with payload to local API: /player/volume Apr 14 15:02:06 volumio volumio[10084]: error: Failed to send command to Spotify local API: /player/volume: Error: Internal Server Error Apr 14 15:02:06 volumio go-librespot[10457]: time="2024-04-14T15:02:06+08:00" level=debug msg="obtained new client token: AACSRdmhdYvrpwwiOUSJNQIqoA0heL29+2clcdw+JvS50ExJu57/yCKoTcWRrN94HohVSO6MBlgB9e+HgIU2QFNK2klhh41i9nKAgYp3k3w+jaGtcpbwZg9wdz0w6DFJ/5BlMdH8mgzHhjl11fGyCjtd87RPfDh4Piyu89zJj0GnduUcgDZLqDe9Lm+FQEVNJXtDPIRi5+UgDoVwGOwdhTngqXXKQzwBaxuxvqqJhfYoEb3+FcatvDWYyd/4vaV6" Apr 14 15:02:07 volumio go-librespot[10457]: time="2024-04-14T15:02:07+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 15:02:07 volumio go-librespot[10457]: time="2024-04-14T15:02:07+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:08 volumio go-librespot[10457]: time="2024-04-14T15:02:08+08:00" level=debug msg="completed challenge" Apr 14 15:02:08 volumio go-librespot[10457]: time="2024-04-14T15:02:08+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 15:02:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:09 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:09 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 372. Apr 14 15:02:11 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:11 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:11 volumio go-librespot[10465]: Librespot-go daemon starting... Apr 14 15:02:11 volumio go-librespot[10465]: time="2024-04-14T15:02:11+08:00" level=info msg="generated new device id: e8c4503c31812faac185828cb3e0f9f411eb9139" Apr 14 15:02:11 volumio go-librespot[10465]: time="2024-04-14T15:02:11+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:12 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:12 volumio go-librespot[10465]: time="2024-04-14T15:02:12+08:00" level=debug msg="new websocket client" Apr 14 15:02:12 volumio volumio[10084]: info: Connection to go-librespot Websocket established Apr 14 15:02:12 volumio go-librespot[10465]: time="2024-04-14T15:02:12+08:00" level=debug msg="obtained new client token: AABFs7xK27i9KsHPaZbYxf2wUHpoK2a2NkQe5cvMGuOZl8blsD+WEpy1gbIhQCEvMqU0YDtDUzuq4g6+0x70nIcOVgw8Xree+94zjKTkXMYIAQj0AwwVFb4w1kpymsYWA3+Fe575bWC8GNMyAb39P0SfGCJaUQw31Ff8KZihDB7xkhOGcAD2oQGYab7ATooLQe30fTp3hJmhBGd9pGQzWzMqvp/vaj0Ed6HULk9jIhXn882o1+UVncwL3nhyDX3v" Apr 14 15:02:13 volumio go-librespot[10465]: time="2024-04-14T15:02:13+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:02:13 volumio go-librespot[10465]: time="2024-04-14T15:02:13+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:14 volumio go-librespot[10465]: time="2024-04-14T15:02:14+08:00" level=debug msg="completed challenge" Apr 14 15:02:14 volumio go-librespot[10465]: time="2024-04-14T15:02: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" Apr 14 15:02:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:14 volumio volumio[10084]: info: Connection to go-librespot Websocket closed Apr 14 15:02:15 volumio volumio[10084]: info: Getting Spotify volume Apr 14 15:02:15 volumio volumio[10084]: (node:10084) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:15 volumio volumio[10084]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 15:02:15 volumio volumio[10084]: (node:10084) 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: 2) Apr 14 15:02:15 volumio volumio[10084]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 14 15:02:15 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:02:15 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:15 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:17 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:17 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 373. Apr 14 15:02:17 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:17 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:17 volumio go-librespot[10474]: Librespot-go daemon starting... Apr 14 15:02:17 volumio go-librespot[10474]: time="2024-04-14T15:02:17+08:00" level=info msg="generated new device id: 3b387a75b227e540306a9c0a30f92bb02df62a16" Apr 14 15:02:17 volumio go-librespot[10474]: time="2024-04-14T15:02:17+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:17 volumio go-librespot[10474]: time="2024-04-14T15:02:17+08:00" level=debug msg="obtained new client token: AAAJqzEUk7Gq0csEgLaNx/WCUhQXpVMf03ziF85k2LLoYUBwZ2ietLTy9RfNx5OB4CpigbNRcv80UKIh6OPYwt4eCA12c4SPN381Tql3eANBQBMiyyIOef41/D69Vx0aG3z2BX0pZNyTinYFiBQ27vAzs+j1aw+tYn8koS9eTb9/gGgh/hhtNcHu86RnknyGyoSiirY5srZnsdVW+MRoK1e9E6C79zTWau/+GU/tlkHfgtP0EWdQrq92Fkg/r/OV" Apr 14 15:02:18 volumio go-librespot[10474]: time="2024-04-14T15:02: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:02:18 volumio go-librespot[10474]: time="2024-04-14T15:02:18+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:19 volumio go-librespot[10474]: time="2024-04-14T15:02:19+08:00" level=debug msg="completed challenge" Apr 14 15:02:19 volumio go-librespot[10474]: time="2024-04-14T15:02:19+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:02:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:20 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:20 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:22 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 374. Apr 14 15:02:22 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:22 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:22 volumio go-librespot[10482]: Librespot-go daemon starting... Apr 14 15:02:22 volumio go-librespot[10482]: time="2024-04-14T15:02:22+08:00" level=info msg="generated new device id: 7914c75f6dfc38a16ad5f117c63d8a07751aff4f" Apr 14 15:02:22 volumio go-librespot[10482]: time="2024-04-14T15:02:22+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:23 volumio go-librespot[10482]: time="2024-04-14T15:02:23+08:00" level=debug msg="obtained new client token: AAATs709O9T+vMdwsAbf6aIhHSCXoi+inwI2nBauBvNYv9z1xeb83zZ/w40bYNPmbKGVjKCb3zpGEafbKNCQVKNOOD5WHj6EmBqtTljCoYgkJckqlDzpIqXwrEyYmVfhQGxvYuoOIsYgIBT2pwTBdvFwHY37gUcXv3wTiaUoyIO8ke9R0HK3Py3jYhIMrCVq6hSuYJO90pmbU5x+IiSPVJFyjIodWd4SAJM47sylnyapPzWX0FJKsd5VndVOLg==" Apr 14 15:02:23 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:23 volumio go-librespot[10482]: time="2024-04-14T15:02:23+08:00" level=debug msg="new websocket client" Apr 14 15:02:23 volumio volumio[10084]: info: Connection to go-librespot Websocket established Apr 14 15:02:23 volumio go-librespot[10482]: time="2024-04-14T15:02: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-gew1.spotify.com:80]" Apr 14 15:02:23 volumio go-librespot[10482]: time="2024-04-14T15:02:23+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:24 volumio go-librespot[10482]: time="2024-04-14T15:02:24+08:00" level=debug msg="completed challenge" Apr 14 15:02:24 volumio go-librespot[10482]: time="2024-04-14T15:02:24+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:02:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:24 volumio volumio[10084]: info: Connection to go-librespot Websocket closed Apr 14 15:02:24 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 14 15:02:24 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:02:24 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 14 15:02:24 volumio volumio[10084]: error: Plugin music_service ytcr failed to complete 'onStart' in a timely fashion Apr 14 15:02:24 volumio volumio[10084]: info: ------------------------------------------- Apr 14 15:02:24 volumio volumio[10084]: info: ----- MyVolumio plugins startup ---- Apr 14 15:02:24 volumio volumio[10084]: info: ------------------------------------------- Apr 14 15:02:24 volumio volumio[10084]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 14 15:02:26 volumio volumio[10084]: info: Getting Spotify volume Apr 14 15:02:26 volumio volumio[10084]: (node:10084) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:26 volumio volumio[10084]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 15:02:26 volumio volumio[10084]: (node:10084) 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: 3) Apr 14 15:02:26 volumio volumio[10084]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 14 15:02:26 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:02:26 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:26 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:27 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:27 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 375. Apr 14 15:02:27 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:27 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:27 volumio go-librespot[10492]: Librespot-go daemon starting... Apr 14 15:02:27 volumio go-librespot[10492]: time="2024-04-14T15:02:27+08:00" level=info msg="generated new device id: e4d95d90f816f7538fcb0b41de8130406e877ae8" Apr 14 15:02:27 volumio go-librespot[10492]: time="2024-04-14T15:02:27+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:28 volumio go-librespot[10492]: time="2024-04-14T15:02:28+08:00" level=debug msg="obtained new client token: AABR1E27vzFjw/pyRObUmRdtrD6srT6/4VQu5z0HBtKWXGBWvBKUINbNbC98jrl1zYuyDvm1S4uF1F0Mr5gQYkt3sYNfWSBRbUyt4DO+9Pcr6FWir5CoeVta12z+nexJGXVrdaKvXhvvIsMtWF0T1DT+i9jD55usczMoGtUVagomBosKY+MqbITIoWKnWCHJraADTHzOamsiiy5/gPoYfYAftuRNZuZcbPykYyXhEy3DbywZuWMyi3pGuxZFK67V" Apr 14 15:02:28 volumio go-librespot[10492]: time="2024-04-14T15:02:28+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:02:29 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 14 15:02:29 volumio volumio[10084]: info: CURURI: music-library Apr 14 15:02:29 volumio go-librespot[10492]: time="2024-04-14T15:02:29+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:29 volumio volumio[10084]: info: Preload queue cleared Apr 14 15:02:29 volumio go-librespot[10492]: time="2024-04-14T15:02:29+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed solving challenge: failed login: BadCredentials" Apr 14 15:02:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:30 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:30 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:31 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 14 15:02:31 volumio volumio[10084]: info: CURURI: music-library/USB Apr 14 15:02:31 volumio volumio[10084]: info: Preload queue cleared Apr 14 15:02:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 376. Apr 14 15:02:32 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:32 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:32 volumio go-librespot[10502]: Librespot-go daemon starting... Apr 14 15:02:32 volumio go-librespot[10502]: time="2024-04-14T15:02:32+08:00" level=info msg="generated new device id: 2d33cfb17cb26836e2d69d6eb6bcbe7be3f338ff" Apr 14 15:02:32 volumio go-librespot[10502]: time="2024-04-14T15:02:32+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:33 volumio go-librespot[10502]: time="2024-04-14T15:02:33+08:00" level=debug msg="obtained new client token: AAA1FufCT9McHpW6KViLEencdTc4hRiwCAgyzdGckYsJj8uERpqccGXYevB6c98020fTc4LLSbiMs9EYCaoPGJFSKKSPZ4soupFJjTtmtOLtSzrc8LcTqDbd2eNX0PJAZ6XSOdVUAso9Sb+DJkwpN6N5Jn2ChgU/I95BfXpZRMZhH0j9oo4b0StPc2z8JBHsFqJfVfG/bCaKwzyFNPbeDKqT9L8jWqSTjIb3iTL92RA41hy9nF0anRWoPSccov9+" Apr 14 15:02:33 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:33 volumio go-librespot[10502]: time="2024-04-14T15:02:33+08:00" level=debug msg="new websocket client" Apr 14 15:02:33 volumio volumio[10084]: info: Connection to go-librespot Websocket established Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Apr 14 15:02:33 volumio volumio[10084]: info: Adding plugin bluetooth to MyMusic Plugins Apr 14 15:02:33 volumio volumio[10084]: info: Adding plugin multiroom to MyMusic Plugins Apr 14 15:02:33 volumio volumio[10084]: info: Adding plugin metavolumio to MyMusic Plugins Apr 14 15:02:33 volumio volumio[10084]: info: Adding plugin cd_controller to MyMusic Plugins Apr 14 15:02:33 volumio volumio[10084]: info: Adding plugin smart_inputs to MyMusic Plugins Apr 14 15:02:33 volumio volumio[10084]: info: Adding plugin tidalconnect to MyMusic Plugins Apr 14 15:02:33 volumio volumio[10084]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Apr 14 15:02:34 volumio go-librespot[10502]: time="2024-04-14T15:02:34+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 15:02:34 volumio go-librespot[10502]: time="2024-04-14T15:02:34+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:34 volumio volumio[10084]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Apr 14 15:02:34 volumio volumio[10084]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Apr 14 15:02:34 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:02:34 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:02:34 volumio volumio[10084]: info: Starting MyVolumio Remote Streaming Endpoints Apr 14 15:02:34 volumio volumio[10084]: info: MyVolumio not started Apr 14 15:02:34 volumio volumio[10084]: info: Initializing device activation check Apr 14 15:02:34 volumio volumio[10084]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Apr 14 15:02:34 volumio volumio[10084]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Apr 14 15:02:34 volumio go-librespot[10502]: time="2024-04-14T15:02:34+08:00" level=debug msg="completed challenge" Apr 14 15:02:34 volumio go-librespot[10502]: time="2024-04-14T15:02:34+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 15:02:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:35 volumio volumio[10084]: info: Starting Streaming Service Transparent Proxy Apr 14 15:02:35 volumio volumio[10084]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Apr 14 15:02:35 volumio volumio[10084]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Apr 14 15:02:35 volumio volumio[10084]: info: Streaming services startup Apr 14 15:02:35 volumio volumio[10084]: info: Starting Streaming Daemon Apr 14 15:02:35 volumio sudo[10518]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Apr 14 15:02:35 volumio sudo[10518]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:02:35 volumio sudo[10518]: pam_unix(sudo:session): session closed for user root Apr 14 15:02:35 volumio volumio[10084]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Apr 14 15:02:35 volumio volumio[10084]: error: Cannot start Volumio Streaming Daemon Apr 14 15:02:35 volumio volumio[10084]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Apr 14 15:02:35 volumio volumio[10084]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Apr 14 15:02:35 volumio volumio[10084]: info: Connection to go-librespot Websocket closed Apr 14 15:02:35 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 14 15:02:35 volumio volumio[10084]: info: CURURI: music-library/USB/A27B-C06F Apr 14 15:02:35 volumio volumio[10084]: info: Preload queue cleared Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/c8，大峡谷..mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/天堂庾澄庆.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/梁山伯与朱丽叶-曹格.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/春泥庾澄庆.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/三国庾澄庆.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/梦回唐朝.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/潇洒的走.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/长城.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/c彩云伴海鸥.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/Wearetheworld-michaeljackson.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/何映达-薇拉.wma Apr 14 15:02:35 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/c8，大峡谷..mp3 in service mpd Apr 14 15:02:35 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C3%84%C3%A1%C2%B9%C3%85%C3%80%C2%AD%C3%8B%C2%B9.%C2%B9%C3%85%C2%B6%C3%B7//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2Fc8%EF%BC%8C%E5%A4%A7%E5%B3%A1%E8%B0%B7..mp3&metadata=false Apr 14 15:02:35 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/c8，大峡谷..mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/天堂庾澄庆.mp3 in service mpd Apr 14 15:02:35 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E5%A4%A9%E5%A0%82%E5%BA%BE%E6%BE%84%E5%BA%86.mp3&metadata=false Apr 14 15:02:35 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/天堂庾澄庆.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/梁山伯与朱丽叶-曹格.mp3 in service mpd Apr 14 15:02:35 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E6%A2%81%E5%B1%B1%E4%BC%AF%E4%B8%8E%E6%9C%B1%E4%B8%BD%E5%8F%B6-%E6%9B%B9%E6%A0%BC.mp3&metadata=false Apr 14 15:02:35 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/梁山伯与朱丽叶-曹格.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/春泥庾澄庆.mp3 in service mpd Apr 14 15:02:35 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C3%A2%C3%97%C2%B3%C3%8E%C3%87%C3%AC/%C2%B9%C3%BE%C3%81%C3%96%C3%8C%C3%AC%C3%8C%C3%83/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E6%98%A5%E6%B3%A5%E5%BA%BE%E6%BE%84%E5%BA%86.mp3&metadata=false Apr 14 15:02:35 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/春泥庾澄庆.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/三国庾澄庆.mp3 in service mpd Apr 14 15:02:35 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C3%A2%C3%97%C2%B3%C3%8E%C3%87%C3%AC/%C2%B9%C3%BE%C3%81%C3%96%C3%8C%C3%AC%C3%8C%C3%83/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E4%B8%89%E5%9B%BD%E5%BA%BE%E6%BE%84%E5%BA%86.mp3&metadata=false Apr 14 15:02:35 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/三国庾澄庆.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/梦回唐朝.mp3 in service mpd Apr 14 15:02:35 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C3%8C%C3%86%C2%B3%C2%AF%C3%80%C3%96%C2%B6%C3%93/%C3%83%C3%8E%C2%BB%C3%98%C3%8C%C3%86%C2%B3%C2%AF/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E6%A2%A6%E5%9B%9E%E5%94%90%E6%9C%9D.mp3&metadata=false Apr 14 15:02:35 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/梦回唐朝.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/潇洒的走.mp3 in service mpd Apr 14 15:02:35 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B8%C3%9F%C3%8A%C2%A4%C3%83%C3%80/%C3%A4%C3%AC%C3%88%C3%B7%C2%B5%C3%84%C3%97%C3%9F/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E6%BD%87%E6%B4%92%E7%9A%84%E8%B5%B0.mp3&metadata=false Apr 14 15:02:35 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/潇洒的走.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/长城.mp3 in service mpd Apr 14 15:02:35 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=http%3A%2F%2Fwww.uptu.com%20-%20Beyond/Beyond%20%C2%B3%C2%AC%C3%94%C2%BD%20Beyond%20Live%2003/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E9%95%BF%E5%9F%8E.mp3&metadata=false Apr 14 15:02:35 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/长城.mp3 Apr 14 15:02:35 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/c彩云伴海鸥.mp3 in service mpd Apr 14 15:02:35 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B8%C3%9F%C3%8A%C2%A4%C3%83%C3%80/%C3%8D%C2%B8%C3%83%C3%B7%C3%93%C3%AA%C2%B9%C2%A4%C3%97%C3%B7%C3%8A%C3%92/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2Fc%E5%BD%A9%E4%BA%91%E4%BC%B4%E6%B5%B7%E9%B8%A5.mp3&metadata=false Apr 14 15:02:35 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/c彩云伴海鸥.mp3 Apr 14 15:02:36 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/Wearetheworld-michaeljackson.mp3 in service mpd Apr 14 15:02:36 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=michael%20jackson/qQ%2C104644489%2C/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FWearetheworld-michaeljackson.mp3&metadata=false Apr 14 15:02:36 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/Wearetheworld-michaeljackson.mp3 Apr 14 15:02:36 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/何映达-薇拉.wma in service mpd Apr 14 15:02:36 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%E4%BD%95%E6%98%A0%E8%BE%BE/%E6%8D%AE%E6%88%91%E6%89%80%E7%9F%A5/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E4%BD%95%E6%98%A0%E8%BE%BE-%E8%96%87%E6%8B%89.wma&metadata=false Apr 14 15:02:36 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/何映达-薇拉.wma Apr 14 15:02:36 volumio volumio[10084]: STREAMING PROXY: Starting server on port 3245 Apr 14 15:02:36 volumio volumio[10084]: Node JS runtime: 14 Apr 14 15:02:36 volumio volumio[10084]: info: Getting Spotify volume Apr 14 15:02:36 volumio volumio[10084]: (node:10084) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:36 volumio volumio[10084]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 15:02:36 volumio volumio[10084]: (node:10084) 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: 4) Apr 14 15:02:36 volumio volumio[10084]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 14 15:02:36 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:02:36 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:36 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:38 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 377. Apr 14 15:02:38 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:38 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:38 volumio go-librespot[10525]: Librespot-go daemon starting... Apr 14 15:02:38 volumio go-librespot[10525]: time="2024-04-14T15:02:38+08:00" level=info msg="generated new device id: b66caa0bd75720ad8ba3f75a4a43f5bcda4b774a" Apr 14 15:02:38 volumio go-librespot[10525]: time="2024-04-14T15:02:38+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:38 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:38 volumio go-librespot[10525]: time="2024-04-14T15:02:38+08:00" level=debug msg="new websocket client" Apr 14 15:02:38 volumio volumio[10084]: info: Connection to go-librespot Websocket established Apr 14 15:02:38 volumio go-librespot[10525]: time="2024-04-14T15:02:38+08:00" level=debug msg="obtained new client token: AADFku+U8udyiWu1srftxFsvMueAlYCTrqhsBxYfdabPoG7N5MTz471+1lWjUEkXkUIGLGeK59qMrgEbXZDPDVY0gkC0bFFuUZOvErtEoV2vT172QmsW3gmFATXjg4amDVm7os+3NvMW0e5yfi1coDu32VdsRX/3f4iXFDBvynQ+oWOPZU50FJdvq6xyZSqG3+2NCDVN3LUQMTSxBbZ92xV5t2XIvea/sKu9lHH+l9Yaa/qH0wFVSky6LRVQboNf" Apr 14 15:02:39 volumio go-librespot[10525]: time="2024-04-14T15:02:39+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 15:02:39 volumio go-librespot[10525]: time="2024-04-14T15:02:39+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:39 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 14 15:02:39 volumio volumio[10084]: info: CURURI: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3) Apr 14 15:02:39 volumio volumio[10084]: info: Preload queue cleared Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/03 - 你的眼神.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/04 - 想你的时候.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/05 - 抉择.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/06 - 我的思念.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/07 - 兺塞曲.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/08 - 渡口.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/09 - 怎么能.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/10 - 恰似你的温柔.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/11 - 儍爱我一次.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Preloading song: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/12 - 谢幕曲.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3 in service mpd Apr 14 15:02:39 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F01%20-%20%E8%A2%AB%E9%81%97%E5%BF%98%E7%9A%84%E6%97%B6%E5%85%89.mp3&metadata=false Apr 14 15:02:39 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3 in service mpd Apr 14 15:02:39 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F02%20-%20%E8%B7%9F%E6%88%91%E8%AF%B4%E7%88%B1%E6%88%91.mp3&metadata=false Apr 14 15:02:39 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3 Apr 14 15:02:39 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/03 - 你的眼神.mp3 in service mpd Apr 14 15:02:39 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F03%20-%20%E4%BD%A0%E7%9A%84%E7%9C%BC%E7%A5%9E.mp3&metadata=false Apr 14 15:02:39 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/03 - 你的眼神.mp3 Apr 14 15:02:39 volumio go-librespot[10525]: time="2024-04-14T15:02:39+08:00" level=debug msg="completed challenge" Apr 14 15:02:39 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/04 - 想你的时候.mp3 in service mpd Apr 14 15:02:39 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F04%20-%20%E6%83%B3%E4%BD%A0%E7%9A%84%E6%97%B6%E5%80%99.mp3&metadata=false Apr 14 15:02:39 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/04 - 想你的时候.mp3 Apr 14 15:02:40 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/05 - 抉择.mp3 in service mpd Apr 14 15:02:40 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F05%20-%20%E6%8A%89%E6%8B%A9.mp3&metadata=false Apr 14 15:02:40 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/05 - 抉择.mp3 Apr 14 15:02:40 volumio go-librespot[10525]: time="2024-04-14T15:02:40+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 15:02:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:40 volumio volumio[10084]: info: Connection to go-librespot Websocket closed Apr 14 15:02:40 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/06 - 我的思念.mp3 in service mpd Apr 14 15:02:40 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F06%20-%20%E6%88%91%E7%9A%84%E6%80%9D%E5%BF%B5.mp3&metadata=false Apr 14 15:02:40 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/06 - 我的思念.mp3 Apr 14 15:02:40 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/07 - 兺塞曲.mp3 in service mpd Apr 14 15:02:40 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F07%20-%20%E5%85%BA%E5%A1%9E%E6%9B%B2.mp3&metadata=false Apr 14 15:02:40 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/07 - 兺塞曲.mp3 Apr 14 15:02:40 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/08 - 渡口.mp3 in service mpd Apr 14 15:02:40 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F08%20-%20%E6%B8%A1%E5%8F%A3.mp3&metadata=false Apr 14 15:02:40 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/08 - 渡口.mp3 Apr 14 15:02:40 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/09 - 怎么能.mp3 in service mpd Apr 14 15:02:40 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F09%20-%20%E6%80%8E%E4%B9%88%E8%83%BD.mp3&metadata=false Apr 14 15:02:40 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/09 - 怎么能.mp3 Apr 14 15:02:40 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/10 - 恰似你的温柔.mp3 in service mpd Apr 14 15:02:40 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F10%20-%20%E6%81%B0%E4%BC%BC%E4%BD%A0%E7%9A%84%E6%B8%A9%E6%9F%94.mp3&metadata=false Apr 14 15:02:40 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/10 - 恰似你的温柔.mp3 Apr 14 15:02:40 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/11 - 儍爱我一次.mp3 in service mpd Apr 14 15:02:40 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F11%20-%20%E5%84%8D%E7%88%B1%E6%88%91%E4%B8%80%E6%AC%A1.mp3&metadata=false Apr 14 15:02:40 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/11 - 儍爱我一次.mp3 Apr 14 15:02:40 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/12 - 谢幕曲.mp3 in service mpd Apr 14 15:02:40 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%C2%B2%C3%8C%C3%87%C3%99/%C3%83%C3%B1%C2%B8%C3%A8%C2%B2%C3%8C%C3%87%C3%99/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E8%94%A1%E7%90%B4.-.%5B%E6%B0%91%E6%AD%8C%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(MP3)%2F12%20-%20%E8%B0%A2%E5%B9%95%E6%9B%B2.mp3&metadata=false Apr 14 15:02:40 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/12 - 谢幕曲.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Preload queue cleared Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::ClearQueue Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::stop Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::clearPlayQueue Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::saveQueue Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushQueue Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::addQueueItems Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::addQueueItems Apr 14 15:02:41 volumio volumio[10084]: info: Preload queue cleared Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/03 - 你的眼神.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/03 - 你的眼神.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/04 - 想你的时候.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/04 - 想你的时候.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/05 - 抉择.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/05 - 抉择.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/06 - 我的思念.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/06 - 我的思念.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/07 - 兺塞曲.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/07 - 兺塞曲.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/08 - 渡口.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/08 - 渡口.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/09 - 怎么能.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/09 - 怎么能.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/10 - 恰似你的温柔.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/10 - 恰似你的温柔.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/11 - 儍爱我一次.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/11 - 儍爱我一次.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/12 - 谢幕曲.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/12 - 谢幕曲.mp3 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushQueue Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::saveQueue Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::updateTrackBlock Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrackBlock Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPlay Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::play index 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::stop Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::play index undefined Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::startPlaybackTimer Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::clearAddPlayTracks USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3 Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand stop Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand stop took 4 milliseconds Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand clear Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:02:41 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand clear took 14 milliseconds Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand add "USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3" Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:02:41 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:02:41 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:02:41 volumio volumio[10084]: error: updateQueue error: null Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:02:41 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 20ms Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand add "USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3" took 14 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 13ms Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 8ms Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand play Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:02:41 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:02:41 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 21ms Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand play took 17 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 16ms Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 10ms Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:02:41 volumio volumio[10084]: info: Getting Spotify volume Apr 14 15:02:41 volumio volumio[10084]: (node:10084) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:41 volumio volumio[10084]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 15:02:41 volumio volumio[10084]: (node:10084) 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: 5) Apr 14 15:02:41 volumio volumio[10084]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand status took 212 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand status took 207 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand status took 206 milliseconds Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:02:41 volumio volumio[10084]: info: Apr 14 15:02:41 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand status took 12 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 10 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 10 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 10 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand status took 8 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand status took 5 milliseconds Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":165,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"±»ÒÅÍüµÄʱ¹â","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3","trackType":"mp3"} Apr 14 15:02:41 volumio volumio[10084]: verbose: CURRENT POSITION 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":102,"duration":165,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"±»ÒÅÍüµÄʱ¹â","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3","trackType":"mp3"} Apr 14 15:02:41 volumio volumio[10084]: verbose: CURRENT POSITION 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus play Apr 14 15:02:41 volumio volumio[10084]: info: Received an update from plugin. extracting info from payload Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":262,"duration":165,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"±»ÒÅÍüµÄʱ¹â","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3","trackType":"mp3"} Apr 14 15:02:41 volumio volumio[10084]: verbose: CURRENT POSITION 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus play Apr 14 15:02:41 volumio volumio[10084]: info: Received an update from plugin. extracting info from payload Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 252ms Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 296ms Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 292ms Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 73 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 73 milliseconds Apr 14 15:02:41 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 72 milliseconds Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:02:41 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":165,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"±»ÒÅÍüµÄʱ¹â","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3","trackType":"mp3"} Apr 14 15:02:41 volumio volumio[10084]: verbose: CURRENT POSITION 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus play Apr 14 15:02:41 volumio volumio[10084]: info: Received an update from plugin. extracting info from payload Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":165,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"±»ÒÅÍüµÄʱ¹â","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3","trackType":"mp3"} Apr 14 15:02:41 volumio volumio[10084]: verbose: CURRENT POSITION 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus play Apr 14 15:02:41 volumio volumio[10084]: info: Received an update from plugin. extracting info from payload Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:02:41 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":165,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"±»ÒÅÍüµÄʱ¹â","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3","trackType":"mp3"} Apr 14 15:02:41 volumio volumio[10084]: verbose: CURRENT POSITION 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus play Apr 14 15:02:41 volumio volumio[10084]: info: Received an update from plugin. extracting info from payload Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:02:41 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:02:41 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:41 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 223ms Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 217ms Apr 14 15:02:41 volumio volumio[10084]: info: ------------------------------ 217ms Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:41 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:43 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:43 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 378. Apr 14 15:02:43 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:43 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:43 volumio go-librespot[10581]: Librespot-go daemon starting... Apr 14 15:02:43 volumio go-librespot[10581]: time="2024-04-14T15:02:43+08:00" level=info msg="generated new device id: d14dedd81908d92e87751f7734fe7b18e44eabf1" Apr 14 15:02:43 volumio go-librespot[10581]: time="2024-04-14T15:02:43+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:43 volumio go-librespot[10581]: time="2024-04-14T15:02:43+08:00" level=debug msg="obtained new client token: AAA5Q9Fxs6BkutdQVYzEKCzMtDu5Q/O0oZ2tfwjj4n3BjnGngyTKiFuVS3IQnkENbH2wTQl4V2+e12aqvZhCDUSK1q9HBuq5paopsTMXr3Hd3QTOVamNGRp7ZTDn2GzvzA7TaGJPFbCcZe5qtRBhwTVsyUGwne0MkDyZSJhlNEwj/d3fvzmTCoQCA78tCkBfr4JzcEuAIlh41gkAquoqW2QZ4Xc5iPxjGQRyQ/dAT/nm3cTP0Jp6OXXU32bf1qVF" Apr 14 15:02:44 volumio go-librespot[10581]: time="2024-04-14T15:02:44+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 15:02:44 volumio go-librespot[10581]: time="2024-04-14T15:02:44+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:45 volumio go-librespot[10581]: time="2024-04-14T15:02:45+08:00" level=debug msg="completed challenge" Apr 14 15:02:45 volumio go-librespot[10581]: time="2024-04-14T15:02:45+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 15:02:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:46 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:46 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:48 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 379. Apr 14 15:02:48 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:48 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:48 volumio go-librespot[10589]: Librespot-go daemon starting... Apr 14 15:02:48 volumio go-librespot[10589]: time="2024-04-14T15:02:48+08:00" level=info msg="generated new device id: 3b082838d4b5a925c6a89c92b5f474d178fca58f" Apr 14 15:02:48 volumio go-librespot[10589]: time="2024-04-14T15:02:48+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:49 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:49 volumio go-librespot[10589]: time="2024-04-14T15:02:49+08:00" level=debug msg="new websocket client" Apr 14 15:02:49 volumio volumio[10084]: info: Connection to go-librespot Websocket established Apr 14 15:02:49 volumio go-librespot[10589]: time="2024-04-14T15:02:49+08:00" level=debug msg="obtained new client token: AACsTNc+qxh++0zsTx6XYazBXoRwhkXeGj4HHAmgdNfGMyRfLcvmTgZs74ont2xfAjRMEKtmdMzNpu5B7r40nGadqrJwFXkBlO+rB38kWN8TARrJ86JkXVgQANEMNpPzNPcTgOenSiUMZIzm2+bKpfQe+LU6ISKLTslw6KxkZfJ+9dQsXzovMJX8CmFOka1XwbSKWbxNtmSyazCQEVk+E1lIHpDdcNR3xn4yh57jUSRpNYK1NN74cvytwJ5mug==" Apr 14 15:02:49 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 14 15:02:49 volumio volumio[10084]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 15:02:49 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:02:49 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:49 volumio go-librespot[10589]: time="2024-04-14T15:02:49+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 15:02:49 volumio go-librespot[10589]: time="2024-04-14T15:02:49+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:50 volumio go-librespot[10589]: time="2024-04-14T15:02:50+08:00" level=debug msg="completed challenge" Apr 14 15:02:50 volumio go-librespot[10589]: time="2024-04-14T15:02: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" Apr 14 15:02:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:50 volumio volumio[10084]: info: Connection to go-librespot Websocket closed Apr 14 15:02:52 volumio volumio[10084]: info: Getting Spotify volume Apr 14 15:02:52 volumio volumio[10084]: (node:10084) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:52 volumio volumio[10084]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 15:02:52 volumio volumio[10084]: (node:10084) 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) Apr 14 15:02:52 volumio volumio[10084]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 15:02:52 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:02:52 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:02:52 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:02:53 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:53 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:53 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 380. Apr 14 15:02:53 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:53 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:53 volumio go-librespot[10597]: Librespot-go daemon starting... Apr 14 15:02:53 volumio go-librespot[10597]: time="2024-04-14T15:02:53+08:00" level=info msg="generated new device id: 519d179d819b1eebce947c11c1fddc04793650b4" Apr 14 15:02:53 volumio go-librespot[10597]: time="2024-04-14T15:02:53+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:54 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:02:54 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Apr 14 15:02:54 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Apr 14 15:02:54 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Apr 14 15:02:54 volumio volumio[10084]: info: CoreCommandRouter::volumioGetBrowseSources Apr 14 15:02:54 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 14 15:02:54 volumio go-librespot[10597]: time="2024-04-14T15:02:54+08:00" level=debug msg="obtained new client token: AAClr6vnlAUyYRYokm86JPyNxPXWXOWLcrJGxIOc68x46E90kB5swOS+N/M64ttYZ13WY47O2K5zXt80jLIgkL6pijY1YXt5EqORMLsJefBWRbZsXdPByT/Jzf1NdtH+OvLSPn6luHXNMjaT5lb7frG3qXqB4TINo31PrVKJqSCcs43wygGTmi8jOg3GhorU31hO9N042jV34+PZl96ZkoGk3eR0rOm5Lkftjob5R6IfRGuYmDvUBlAvm+oR8pnO" Apr 14 15:02:54 volumio go-librespot[10597]: time="2024-04-14T15:02: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:02:55 volumio go-librespot[10597]: time="2024-04-14T15:02:55+08:00" level=debug msg="completed keyexchange" Apr 14 15:02:55 volumio volumio[10084]: error: MyVolumio Plugin failed to authenticate in a timely fashion Apr 14 15:02:55 volumio volumio[10084]: info: Completed starting MyVolumio Plugin Apr 14 15:02:55 volumio volumio[10084]: info: BOOT COMPLETED Apr 14 15:02:55 volumio volumio[10084]: [Metrics] CommandRouter: 100s 582.17ms Apr 14 15:02:55 volumio volumio[10084]: info: CoreCommandRouter::volumiosetStartupVolume Apr 14 15:02:55 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:02:55 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:02:55 volumio volumio[10084]: info: CoreCommandRouter::Close All Modals sent Apr 14 15:02:55 volumio volumio[10084]: info: CoreCommandRouter::Close All Modals sent Apr 14 15:02:55 volumio volumio[10084]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Apr 14 15:02:55 volumio volumio[10084]: aplay: main:828: audio open error: Device or resource busy Apr 14 15:02:55 volumio go-librespot[10597]: time="2024-04-14T15:02:55+08:00" level=debug msg="completed challenge" Apr 14 15:02:56 volumio go-librespot[10597]: time="2024-04-14T15:02:56+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:02:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:02:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:02:56 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Apr 14 15:02:56 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 14 15:02:56 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Apr 14 15:02:56 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:56 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:02:58 volumio volumio[10084]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 14 15:02:58 volumio volumio[10084]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 14 15:02:59 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:02:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 381. Apr 14 15:02:59 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:02:59 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:02:59 volumio go-librespot[10635]: Librespot-go daemon starting... Apr 14 15:02:59 volumio go-librespot[10635]: time="2024-04-14T15:02:59+08:00" level=info msg="generated new device id: 4f494fc0396facd129155c45f9b148e0b395c2e8" Apr 14 15:02:59 volumio go-librespot[10635]: time="2024-04-14T15:02:59+08:00" level=debug msg="stored credentials not found" Apr 14 15:02:59 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:02:59 volumio go-librespot[10635]: time="2024-04-14T15:02:59+08:00" level=debug msg="new websocket client" Apr 14 15:02:59 volumio volumio[10084]: info: Connection to go-librespot Websocket established Apr 14 15:02:59 volumio go-librespot[10635]: time="2024-04-14T15:02:59+08:00" level=debug msg="obtained new client token: AACyLIp7U+Z30PhhnKFOy7oMSrBCOCFwN3tD3jxKNgYY8M0T4anAxTwaZoiNvZk7MQaJh9f7hTKbFpUKxeZG6UMKxvs70tR6jGOnIt56oiloWjTOQudFQS7X2jKTvKm0J2T9orcfsVhrCmJbeO1tjT+QY8soHXlMGANcRM2JhDhIgUAZjmHELUHbyzGIZsIjex8HOz/bh3N6r3qykGakda01UGsU5iBXlgFZzXjdTBliF+6j3PQpPVARYVF0iTgr" Apr 14 15:03:00 volumio volumio[10084]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 9 Apr 14 15:03:00 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:03:00 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:03:00 volumio go-librespot[10635]: time="2024-04-14T15:03:00+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:03:00 volumio go-librespot[10635]: time="2024-04-14T15:03:00+08:00" level=debug msg="completed keyexchange" Apr 14 15:03:01 volumio go-librespot[10635]: time="2024-04-14T15:03:01+08:00" level=debug msg="completed challenge" Apr 14 15:03:01 volumio go-librespot[10635]: time="2024-04-14T15:03: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 15:03:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:03:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:03:01 volumio volumio[10084]: info: Connection to go-librespot Websocket closed Apr 14 15:03:02 volumio volumio[10084]: info: Getting Spotify volume Apr 14 15:03:02 volumio volumio[10084]: (node:10084) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:03:02 volumio volumio[10084]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 15:03:02 volumio volumio[10084]: (node:10084) 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 15:03:02 volumio volumio[10084]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 14 15:03:02 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:03:02 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:03:02 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:04 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:03:04 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:03:04 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:03:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 382. Apr 14 15:03:04 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:03:04 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:03:04 volumio go-librespot[10649]: Librespot-go daemon starting... Apr 14 15:03:04 volumio go-librespot[10649]: time="2024-04-14T15:03:04+08:00" level=info msg="generated new device id: 65a634a15aefe413ad11381220eaa2d7b4fffe44" Apr 14 15:03:04 volumio go-librespot[10649]: time="2024-04-14T15:03:04+08:00" level=debug msg="stored credentials not found" Apr 14 15:03:05 volumio go-librespot[10649]: time="2024-04-14T15:03:05+08:00" level=debug msg="obtained new client token: AADg31BdqIbkoSFo7IjO7S8DG3Go2ywaBaM/mIcXTqEc9FJ780M7dCZiLO0c6BQTr0ScS+HpL9lQqt+cmMTZGFZJTOvHMU1r67RcBD990i6kQZY1+zmFbp5HEf+KJl31iw8hko4EbP2xjjEW3Rcc1nVN+i2AyasRBrLEwWyCBQ9vut5Kcnh+20O8AQSrmSGUEmW/wPPgjKO7LRcFw1snrnpT42vO5D5mWjxdVZmTuqua6zzt8xJYPQ52S4p6yoOB" Apr 14 15:03:06 volumio go-librespot[10649]: time="2024-04-14T15:03: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-gew1.spotify.com:80]" Apr 14 15:03:06 volumio go-librespot[10649]: time="2024-04-14T15:03:06+08:00" level=debug msg="completed keyexchange" Apr 14 15:03:07 volumio go-librespot[10649]: time="2024-04-14T15:03:07+08:00" level=debug msg="completed challenge" Apr 14 15:03:07 volumio go-librespot[10649]: time="2024-04-14T15:03: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" Apr 14 15:03:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:03:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:03:07 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:03:07 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:03:10 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:03:10 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:03:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:03:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 383. Apr 14 15:03:10 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:03:10 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:03:10 volumio go-librespot[10657]: Librespot-go daemon starting... Apr 14 15:03:10 volumio go-librespot[10657]: time="2024-04-14T15:03:10+08:00" level=info msg="generated new device id: a0e8679c7ad35319976cb510933bd093104adc89" Apr 14 15:03:10 volumio go-librespot[10657]: time="2024-04-14T15:03:10+08:00" level=debug msg="stored credentials not found" Apr 14 15:03:11 volumio go-librespot[10657]: time="2024-04-14T15:03:11+08:00" level=debug msg="obtained new client token: AABARb0nasKfGNulFJipL8sis2UOtNPKKDi2yRF3aBO05GmbsXLCHNTSY6NfL566+g67n+B2N8LJQHwphkaHSDEKyZ5fFnyn3RMsEBhy/2uHTWAbescxAPjqIowqv1v6BqhdAExyZxEGyp1tmo1pvOkh+b4SNNS2BdSSpbSyJhuTMKZu5lB9yj/gnoGHBnLA+N5Afb/+f0mahveg8mKeE2dzMW6MhPW9AyNTvet5Y02rMhNRYDOGnoYfuG9M4A==" Apr 14 15:03:11 volumio go-librespot[10657]: time="2024-04-14T15:03: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:03:11 volumio go-librespot[10657]: time="2024-04-14T15:03:11+08:00" level=debug msg="completed keyexchange" Apr 14 15:03:12 volumio go-librespot[10657]: time="2024-04-14T15:03:12+08:00" level=debug msg="completed challenge" Apr 14 15:03:12 volumio go-librespot[10657]: time="2024-04-14T15:03: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 15:03:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:03:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:03:13 volumio volumio[10084]: info: Preload queue cleared Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::ClearQueue Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::stop Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::stPlaybackTimer Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::updateTrackBlock Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrackBlock Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::serviceStop Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 0 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::serviceStop Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::stop Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand stop Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::clearPlayQueue Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::saveQueue Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushQueue Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::addQueueItems Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::addQueueItems Apr 14 15:03:13 volumio volumio[10084]: info: Preload queue cleared Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/01 - 被遗忘的时光.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/03 - 你的眼神.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/03 - 你的眼神.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/04 - 想你的时候.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/04 - 想你的时候.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/05 - 抉择.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/05 - 抉择.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/06 - 我的思念.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/06 - 我的思念.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/07 - 兺塞曲.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/07 - 兺塞曲.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/08 - 渡口.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/08 - 渡口.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/09 - 怎么能.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/09 - 怎么能.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/10 - 恰似你的温柔.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/10 - 恰似你的温柔.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/11 - 儍爱我一次.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/11 - 儍爱我一次.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/12 - 谢幕曲.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/12 - 谢幕曲.mp3 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushQueue Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::saveQueue Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::updateTrackBlock Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrackBlock Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPlay Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::play index 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::stop Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::play index undefined Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::startPlaybackTimer Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::clearAddPlayTracks USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3 Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand stop Apr 14 15:03:13 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand stop took 81 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand stop took 24 milliseconds Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand clear Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:03:13 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand status took 63 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand clear took 62 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand status took 61 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand status took 58 milliseconds Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand add "USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3" Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:03:13 volumio volumio[10084]: verbose: CURRENT POSITION 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState stateService stop Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: No code Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:03:13 volumio volumio[10084]: verbose: CURRENT POSITION 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState stateService stop Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: No code Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 187ms Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 190ms Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:03:13 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:03:13 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:03:13 volumio volumio[10084]: error: updateQueue error: null Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:03:13 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 177ms Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 175 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand add "USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3" took 176 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 47ms Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 47ms Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand play Apr 14 15:03:13 volumio volumio[10084]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 247ms Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:03:13 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces system playlist update Apr 14 15:03:13 volumio volumio[10084]: info: Ignoring MPD Status Update Apr 14 15:03:13 volumio volumio[10084]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 14 15:03:13 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 45ms Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand play took 37 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 37ms Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 36ms Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:03:13 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:03:13 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:13 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:13 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:13 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:13 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:13 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand status took 217 milliseconds Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand status took 219 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand status took 218 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":225,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"¸úÎÒ˵°®ÎÒ","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3","trackType":"mp3"} Apr 14 15:03:13 volumio volumio[10084]: verbose: CURRENT POSITION 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 228ms Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:03:13 volumio volumio[10084]: info: Apr 14 15:03:13 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::getState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand status took 14 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 12 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 11 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand status took 5 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand status took 3 milliseconds Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseState Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":217,"duration":225,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"¸úÎÒ˵°®ÎÒ","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3","trackType":"mp3"} Apr 14 15:03:13 volumio volumio[10084]: verbose: CURRENT POSITION 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus play Apr 14 15:03:13 volumio volumio[10084]: info: Received an update from plugin. extracting info from payload Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":274,"duration":225,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"¸úÎÒ˵°®ÎÒ","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3","trackType":"mp3"} Apr 14 15:03:13 volumio volumio[10084]: verbose: CURRENT POSITION 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus play Apr 14 15:03:13 volumio volumio[10084]: info: Received an update from plugin. extracting info from payload Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 334ms Apr 14 15:03:13 volumio volumio[10084]: info: ------------------------------ 334ms Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 102 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 101 milliseconds Apr 14 15:03:13 volumio volumio[10084]: info: sendMpdCommand playlistinfo took 100 milliseconds Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:03:13 volumio volumio[10084]: verbose: ControllerMpd::parseTrackInfo Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":225,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"¸úÎÒ˵°®ÎÒ","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3","trackType":"mp3"} Apr 14 15:03:13 volumio volumio[10084]: verbose: CURRENT POSITION 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus play Apr 14 15:03:13 volumio volumio[10084]: info: Received an update from plugin. extracting info from payload Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":225,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"¸úÎÒ˵°®ÎÒ","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3","trackType":"mp3"} Apr 14 15:03:13 volumio volumio[10084]: verbose: CURRENT POSITION 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus play Apr 14 15:03:13 volumio volumio[10084]: info: Received an update from plugin. extracting info from payload Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: ControllerMpd::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::servicePushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":225,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"¸úÎÒ˵°®ÎÒ","artist":"²ÌÇÙ","album":"Ãñ¸è²ÌÇÙ","uri":"USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3)/02 - 跟我说爱我.mp3","trackType":"mp3"} Apr 14 15:03:13 volumio volumio[10084]: verbose: CURRENT POSITION 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState stateService play Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::syncState currentStatus play Apr 14 15:03:13 volumio volumio[10084]: info: Received an update from plugin. extracting info from payload Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:13 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:13 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:13 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:14 volumio volumio[10084]: info: ------------------------------ 303ms Apr 14 15:03:14 volumio volumio[10084]: info: ------------------------------ 294ms Apr 14 15:03:14 volumio volumio[10084]: info: ------------------------------ 294ms Apr 14 15:03:14 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:14 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:14 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:14 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:14 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:14 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:14 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:14 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:14 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:14 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:03:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 384. Apr 14 15:03:15 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:03:15 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:03:15 volumio go-librespot[10678]: Librespot-go daemon starting... Apr 14 15:03:15 volumio go-librespot[10678]: time="2024-04-14T15:03:15+08:00" level=info msg="generated new device id: 2138b334ef93776e1834a9468c1f9db38f8908ec" Apr 14 15:03:15 volumio go-librespot[10678]: time="2024-04-14T15:03:15+08:00" level=debug msg="stored credentials not found" Apr 14 15:03:16 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:03:16 volumio go-librespot[10678]: time="2024-04-14T15:03:16+08:00" level=debug msg="new websocket client" Apr 14 15:03:16 volumio volumio[10084]: info: Connection to go-librespot Websocket established Apr 14 15:03:16 volumio go-librespot[10678]: time="2024-04-14T15:03:16+08:00" level=debug msg="obtained new client token: AAAPkm61qKzAtlQtcvCj9YQ2pIqQfcg3+OIHLJ/Yo8unjxWuf6j/tmuklv8acNQyBKldIVx+zAGObdsPwSjswI7zm9kEvUTOepy5xwohxTfeMwN8MEv383JfFKUVhQ/WOgCgTduA+Jc/3PWMixFmFHOXdmE5cBPFhahQYeApbmAf+qcSXfU6CRPsacosZ2ycOdLPLaHnacosSsQ40HvgGDbCaoUHz3TGGPTxfSfohgf8uKKNQgqYXixemKcZx8BZ" Apr 14 15:03:17 volumio go-librespot[10678]: time="2024-04-14T15:03:17+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:03:17 volumio go-librespot[10678]: time="2024-04-14T15:03:17+08:00" level=debug msg="completed keyexchange" Apr 14 15:03:17 volumio go-librespot[10678]: time="2024-04-14T15:03:17+08:00" level=debug msg="completed challenge" Apr 14 15:03:18 volumio go-librespot[10678]: time="2024-04-14T15:03: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 15:03:18 volumio volumio[10084]: info: Connection to go-librespot Websocket closed Apr 14 15:03:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:03:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:03:19 volumio volumio[10084]: info: Getting Spotify volume Apr 14 15:03:19 volumio volumio[10084]: (node:10084) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:03:19 volumio volumio[10084]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 15:03:19 volumio volumio[10084]: (node:10084) 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 15:03:19 volumio volumio[10084]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 14 15:03:19 volumio volumio[10084]: info: CoreCommandRouter::volumioGetState Apr 14 15:03:19 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:19 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:21 volumio volumio[10084]: info: Initializing connection to go-librespot Websocket Apr 14 15:03:21 volumio volumio[10084]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:03:21 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:03:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 385. Apr 14 15:03:21 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:03:21 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:03:21 volumio go-librespot[10686]: Librespot-go daemon starting... Apr 14 15:03:21 volumio go-librespot[10686]: time="2024-04-14T15:03:21+08:00" level=info msg="generated new device id: 5869cc102a9610f884801d3bb402a762109849fa" Apr 14 15:03:21 volumio go-librespot[10686]: time="2024-04-14T15:03:21+08:00" level=debug msg="stored credentials not found" Apr 14 15:03:21 volumio go-librespot[10686]: time="2024-04-14T15:03:21+08:00" level=debug msg="obtained new client token: AADjiZLzTYE8mAgkyg8vI+zMbloXAyH7JiWTP7qL5tCSrerFeXKgR+vGvx3S1rIKSDa8xoY5wMFFnrf4zI7wuKGrT58znaHaYT0Oal37Yyo9UouE9zqp3vegPR/YjpHmypMm8axwLB6464OG53Y2FyH0TSpKP2bE02RwEEAKFGuB0OJdZm/V2ei+B17cqbn1T/Yyk9ajM9BfkA/6YYS+qpntWLwuwTz+AFEAqNJCrCaRS6XAJFTS+fpfpa7BEp3H" Apr 14 15:03:22 volumio go-librespot[10686]: time="2024-04-14T15:03: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 15:03:22 volumio go-librespot[10686]: time="2024-04-14T15:03:22+08:00" level=debug msg="completed keyexchange" Apr 14 15:03:23 volumio volumio[10084]: info: Preload queue cleared Apr 14 15:03:23 volumio volumio[10084]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 14 15:03:23 volumio volumio[10084]: info: CoreStateMachine::ClearQueue Apr 14 15:03:23 volumio volumio[10084]: info: CoreStateMachine::stop Apr 14 15:03:23 volumio volumio[10084]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:03:23 volumio volumio[10084]: info: CoreStateMachine::stPlaybackTimer Apr 14 15:03:23 volumio volumio[10084]: info: CoreStateMachine::updateTrackBlock Apr 14 15:03:23 volumio volumio[10084]: info: CorePlayQueue::getTrackBlock Apr 14 15:03:23 volumio volumio[10084]: info: CoreStateMachine::pushState Apr 14 15:03:23 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:23 volumio volumio[10084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:03:23 volumio volumio[10084]: info: CoreCommandRouter::volumioPushState Apr 14 15:03:23 volumio volumio[10084]: info: CoreStateMachine::serviceStop Apr 14 15:03:23 volumio volumio[10084]: info: CorePlayQueue::getTrack 1 Apr 14 15:03:23 volumio volumio[10084]: info: CoreCommandRouter::serviceStop Apr 14 15:03:23 volumio volumio[10084]: info: ControllerMpd::stop Apr 14 15:03:23 volumio volumio[10084]: verbose: ControllerMpd::sendMpdCommand stop Apr 14 15:03:23 volumio volumio[10084]: info: CorePlayQueue::clearPlayQueue Apr 14 15:03:23 volumio volumio[10084]: info: CorePlayQueue::saveQueue Apr 14 15:03:23 volumio volumio[10084]: info: CoreCommandRouter::volumioPushQueue Apr 14 15:03:23 volumio volumio[10084]: info: CoreStateMachine::addQueueItems Apr 14 15:03:23 volumio volumio[10084]: info: CorePlayQueue::addQueueItems Apr 14 15:03:23 volumio volumio[10084]: info: Preload queue cleared Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/c8，大峡谷..mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/c8，大峡谷..mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/天堂庾澄庆.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/天堂庾澄庆.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/梁山伯与朱丽叶-曹格.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/梁山伯与朱丽叶-曹格.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/春泥庾澄庆.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/春泥庾澄庆.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/三国庾澄庆.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/三国庾澄庆.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/梦回唐朝.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/梦回唐朝.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/潇洒的走.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/潇洒的走.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/长城.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/长城.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/c彩云伴海鸥.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/c彩云伴海鸥.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/Wearetheworld-michaeljackson.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/Wearetheworld-michaeljackson.mp3 Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/何映达-薇拉.wma Apr 14 15:03:23 volumio volumio[10084]: info: Using cached record of: music-library/USB/A27B-C06F/何映达-薇拉.wma Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/HRP754-2[雨果发烧碟01] Apr 14 15:03:23 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/HRP754-2[雨果发烧碟01] in service mpd Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/王杰 Apr 14 15:03:23 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/王杰 in service mpd Apr 14 15:03:23 volumio volumio[10084]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3) Apr 14 15:03:23 volumio volumio[10084]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3) in service mpd Apr 14 15:03:23 volumio volumio[10084]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:03:23 volumio volumio[10084]: info: Apr 14 15:03:23 volumio volumio[10084]: ---------------------------- MPD announces state update: player Apr 14 15:03:23 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FCDImage.ape&metadata=false Apr 14 15:03:23 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01]/CDImage.ape Apr 14 15:03:23 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%3F%3F%3F%3F/%3F%3F%3F%3F%3F%3F%3F%D5%B5%3F01/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FCDImage.cue&metadata=false Apr 14 15:03:23 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01]/CDImage.cue Apr 14 15:03:23 volumio volumio[10084]: info: ALBUMART /albumart?cacheid=378&web=%3F%3F%3F%3F/%3F%3F%3F%3F%3F%3F%3F%D5%B5%3F01/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FCDImage.cue&metadata=false Apr 14 15:03:23 volumio volumio[10084]: info: URI /mnt/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01]/CDImage.cue Apr 14 15:03:23 volumio volumio[10084]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 15:03:23 volumio volumio[10084]: Error: Unable to resolve or reject the same promise twice Apr 14 15:03:23 volumio volumio[10084]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Apr 14 15:03:23 volumio volumio[10084]: at /volumio/app/plugins/music_service/mpd/index.js:2568:21 Apr 14 15:03:23 volumio volumio[10084]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Apr 14 15:03:23 volumio volumio[10084]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Apr 14 15:03:23 volumio volumio[10084]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Apr 14 15:03:23 volumio volumio[10084]: at Socket.emit (events.js:315:20) Apr 14 15:03:23 volumio volumio[10084]: at addChunk (internal/streams/readable.js:309:12) Apr 14 15:03:23 volumio volumio[10084]: at readableAddChunk (internal/streams/readable.js:280:11) Apr 14 15:03:23 volumio volumio[10084]: at Socket.Readable.push (internal/streams/readable.js:223:10) Apr 14 15:03:23 volumio volumio[10084]: at Pipe.onStreamRead (internal/stream_base_commons.js:188:23) Apr 14 15:03:23 volumio volumio[10084]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 15:03:23 volumio go-librespot[10686]: time="2024-04-14T15:03:23+08:00" level=debug msg="completed challenge" Apr 14 15:03:23 volumio go-librespot[10686]: time="2024-04-14T15:03: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 15:03:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:03:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:03:23 volumio sudo[10703]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-14 15:02 Apr 14 15:03:23 volumio sudo[10703]: 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"