-- Logs begin at Thu 2019-02-14 18:11:59 CST, end at Sat 2024-04-27 12:41:41 CST. -- Apr 27 12:40:00 volumio volumio[858]: info: Getting Spotify volume Apr 27 12:40:00 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Apr 27 12:40:00 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:00 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:02 volumio go-librespot[2028]: time="2024-04-27T12:40:02+08:00" level=debug msg="completed keyexchange" Apr 27 12:40:02 volumio go-librespot[2028]: time="2024-04-27T12:40:02+08:00" level=debug msg="completed challenge" Apr 27 12:40:03 volumio go-librespot[2028]: time="2024-04-27T12:40: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 27 12:40:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:40:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:40:03 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 27 12:40:03 volumio volumio[858]: at connResetException (internal/errors.js:607:14) Apr 27 12:40:03 volumio volumio[858]: at Socket.socketOnEnd (_http_client.js:493:23) Apr 27 12:40:03 volumio volumio[858]: at Socket.emit (events.js:327:22) Apr 27 12:40:03 volumio volumio[858]: at endReadableNT (internal/streams/readable.js:1327:12) Apr 27 12:40:03 volumio volumio[858]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Apr 27 12:40:03 volumio volumio[858]: (node:858) 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: 18) Apr 27 12:40:03 volumio volumio[858]: info: Connection to go-librespot Websocket closed Apr 27 12:40:06 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:06 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:40:07 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:40:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Apr 27 12:40:07 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:40:07 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:40:07 volumio go-librespot[2037]: Librespot-go daemon starting... Apr 27 12:40:07 volumio go-librespot[2037]: time="2024-04-27T12:40:07+08:00" level=info msg="generated new device id: c377a4768382e29647ed26ea8384e2aa9179fc1f" Apr 27 12:40:07 volumio go-librespot[2037]: time="2024-04-27T12:40:07+08:00" level=debug msg="stored credentials not found" Apr 27 12:40:09 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:09 volumio go-librespot[2037]: time="2024-04-27T12:40:09+08:00" level=debug msg="new websocket client" Apr 27 12:40:09 volumio volumio[858]: info: Connection to go-librespot Websocket established Apr 27 12:40:12 volumio volumio[858]: info: Getting Spotify volume Apr 27 12:40:13 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Apr 27 12:40:13 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:13 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:21 volumio go-librespot[2037]: time="2024-04-27T12:40:21+08:00" level=debug msg="obtained new client token: AACKFisd9Or3xFRdDAv313HxMgOVdHsjJrJ7JVTIl9bNOBO/OLu/Uk2JgsIl1KiZmWSZRDw4HA92/xx+mQi9Nr8MdBlyYXgBh5W4jMJIY96vwXTgKGfR2qV4e6tbEVzHqa2IWbDEnQBXJDuYk02mgCL9OazrzexexcPPxTcI1OOmM6rE+hhKa3IWtzcINqxn4TV5SuBA/DZ/tN9fTFgCStAf+XsFnEZI+vdtdo1y9HMopzQCacc8g4taMXLSfh8=" Apr 27 12:40:24 volumio go-librespot[2037]: time="2024-04-27T12:40:24+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 27 12:40:26 volumio go-librespot[2037]: time="2024-04-27T12:40:26+08:00" level=debug msg="completed keyexchange" Apr 27 12:40:27 volumio go-librespot[2037]: time="2024-04-27T12:40:27+08:00" level=debug msg="completed challenge" Apr 27 12:40:27 volumio go-librespot[2037]: time="2024-04-27T12:40:27+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 27 12:40:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:40:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:40:27 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 27 12:40:27 volumio volumio[858]: at connResetException (internal/errors.js:607:14) Apr 27 12:40:27 volumio volumio[858]: at Socket.socketOnEnd (_http_client.js:493:23) Apr 27 12:40:27 volumio volumio[858]: at Socket.emit (events.js:327:22) Apr 27 12:40:27 volumio volumio[858]: at endReadableNT (internal/streams/readable.js:1327:12) Apr 27 12:40:27 volumio volumio[858]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Apr 27 12:40:27 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 19) Apr 27 12:40:27 volumio volumio[858]: info: Connection to go-librespot Websocket closed Apr 27 12:40:30 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:30 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:40:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:40:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Apr 27 12:40:30 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:40:30 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:40:30 volumio go-librespot[2092]: Librespot-go daemon starting... Apr 27 12:40:30 volumio go-librespot[2092]: time="2024-04-27T12:40:30+08:00" level=info msg="generated new device id: c2c9afa35ffbe8fbe32ece3ec3d4f0f5ebbb38ce" Apr 27 12:40:30 volumio go-librespot[2092]: time="2024-04-27T12:40:30+08:00" level=debug msg="stored credentials not found" Apr 27 12:40:31 volumio go-librespot[2092]: time="2024-04-27T12:40:31+08:00" level=debug msg="obtained new client token: AACUcQZZk4Phl9wvueLm5oEfsMgwaZ2Rq67pftv9FGZPcrVAxJ0WuuplOI/9wKJvXJQUmZVAK3mWlCyQRnnZaT/jYEvCrQnAfvOq95qxG/9lsPmYgavQ2Na29IkynZnEhejQ/pN5/oAPRabSNabR/Q3wgvBtmbuJcNlcBhaZSm45EKKRztNjDaqZYPGJP1P2a1GNpwNIokQtDXmp1oHEbUaoOKuv2SmWtIRZJyBf2u+ZqM3fu8OX+hr2aV4/hjo=" Apr 27 12:40:33 volumio go-librespot[2092]: time="2024-04-27T12:40:33+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 27 12:40:33 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:33 volumio go-librespot[2092]: time="2024-04-27T12:40:33+08:00" level=debug msg="new websocket client" Apr 27 12:40:33 volumio volumio[858]: info: Connection to go-librespot Websocket established Apr 27 12:40:33 volumio go-librespot[2092]: time="2024-04-27T12:40:33+08:00" level=debug msg="completed keyexchange" Apr 27 12:40:34 volumio go-librespot[2092]: time="2024-04-27T12:40:34+08:00" level=debug msg="completed challenge" Apr 27 12:40:34 volumio go-librespot[2092]: time="2024-04-27T12:40: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 27 12:40:34 volumio volumio[858]: info: Connection to go-librespot Websocket closed Apr 27 12:40:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:40:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:40:34 volumio volumio[858]: verbose: New Socket.io Connection to 192.168.121.192 from 192.168.121.237 UA: Mozilla/5.0 (Linux; Android 13; SM-S9010 Build/TP1A.220624.014; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/111.0.5563.116 Mobile Safari/537.36 Total Clients: 8 Apr 27 12:40:34 volumio volumio[858]: verbose: New Socket.io Connection to 192.168.121.192 from 192.168.121.237 UA: Mozilla/5.0 (Linux; Android 13; SM-S9010 Build/TP1A.220624.014; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/111.0.5563.116 Mobile Safari/537.36 Total Clients: 9 Apr 27 12:40:36 volumio volumio[858]: info: Getting Spotify volume Apr 27 12:40:36 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:40:36 volumio volumio[858]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 27 12:40:36 volumio volumio[858]: (node:858) 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: 20) Apr 27 12:40:36 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 27 12:40:36 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:36 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:37 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:37 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:40:37 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:40:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. Apr 27 12:40:37 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:40:37 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:40:37 volumio go-librespot[2101]: Librespot-go daemon starting... Apr 27 12:40:37 volumio go-librespot[2101]: time="2024-04-27T12:40:37+08:00" level=info msg="generated new device id: 73dffaf3cc30214264ce97f8c4ae156bdabe5fc1" Apr 27 12:40:37 volumio go-librespot[2101]: time="2024-04-27T12:40:37+08:00" level=debug msg="stored credentials not found" Apr 27 12:40:38 volumio go-librespot[2101]: time="2024-04-27T12:40:38+08:00" level=debug msg="obtained new client token: AADIWEPRHaEZwv+p1mRWffqTEAmOZlsyQ+O3NRTrIzOIE+i3wQNN9qz9/Kvvk3bNxesgK359EC+ZFDP1OgbOuVbfet0TU03yWOGJlDdBkOb6QTkwgiMmr8eV25TsKwd/KSA0vQFlDPpOfHueCvCOJID/c0MyQCL7jHw7KsxgnLRa1xkCQDL50st/Pav4gg+fI/oiKmx/a6rQ+yV9Yks441uDmeq9PcLBd6C02RhhFudsvqCrgDvwJ2OduN1TtlE=" Apr 27 12:40:39 volumio go-librespot[2101]: time="2024-04-27T12:40: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 27 12:40:39 volumio go-librespot[2101]: time="2024-04-27T12:40:39+08:00" level=debug msg="completed keyexchange" Apr 27 12:40:40 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:40 volumio volumio[858]: info: Connection to go-librespot Websocket established Apr 27 12:40:40 volumio go-librespot[2101]: time="2024-04-27T12:40:40+08:00" level=debug msg="new websocket client" Apr 27 12:40:40 volumio go-librespot[2101]: time="2024-04-27T12:40:40+08:00" level=debug msg="completed challenge" Apr 27 12:40:40 volumio go-librespot[2101]: time="2024-04-27T12:40: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 27 12:40:40 volumio volumio[858]: verbose: New Socket.io Connection to 192.168.121.192 from 192.168.121.237 UA: Mozilla/5.0 (Linux; Android 13; SM-S9010 Build/TP1A.220624.014; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/111.0.5563.116 Mobile Safari/537.36 Total Clients: 10 Apr 27 12:40:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:40:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:40:40 volumio volumio[858]: info: Connection to go-librespot Websocket closed Apr 27 12:40:43 volumio volumio[858]: info: Getting Spotify volume Apr 27 12:40:43 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:40:43 volumio volumio[858]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 27 12:40:43 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 21) Apr 27 12:40:43 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Apr 27 12:40:43 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:43 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:43 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:43 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:40:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:40:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. Apr 27 12:40:43 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:40:44 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:40:44 volumio go-librespot[2109]: Librespot-go daemon starting... Apr 27 12:40:44 volumio go-librespot[2109]: time="2024-04-27T12:40:44+08:00" level=info msg="generated new device id: 8afd05a79ff9590aa2b0abfad0a6dbdf153ee749" Apr 27 12:40:44 volumio go-librespot[2109]: time="2024-04-27T12:40:44+08:00" level=debug msg="stored credentials not found" Apr 27 12:40:44 volumio go-librespot[2109]: time="2024-04-27T12:40:44+08:00" level=debug msg="obtained new client token: AAAsKIBosT4b9uVKKLlxmLIudzPElYpF6Kbyf5OO6Q1cPKXi4AFoKcsBLrTZETF7ysn0WxR0gS4ieG+xSzrGxXKurkfkivlavr56JldD2Y6di0rwZV/R4wjE/B5gk12DU1b10dGMclOI7oKtUcVUuqyCDEx1vtBiuRx30l43yolcJwm9ssZIs8hQkLCS6PzZP0JzAOVRh7QCSOIsCvkR4IV7OD4XGzWwlZ3wW4HRajPgwoxIpWTgCqARHjRPZBE=" Apr 27 12:40:45 volumio go-librespot[2109]: time="2024-04-27T12:40:45+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 27 12:40:46 volumio volumio[858]: verbose: New Socket.io Connection to 192.168.121.192 from 192.168.121.237 UA: Mozilla/5.0 (Linux; Android 13; SM-S9010 Build/TP1A.220624.014; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/111.0.5563.116 Mobile Safari/537.36 Total Clients: 11 Apr 27 12:40:46 volumio go-librespot[2109]: time="2024-04-27T12:40:46+08:00" level=debug msg="completed keyexchange" Apr 27 12:40:46 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:46 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:46 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:46 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:46 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:46 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:46 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:46 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetVisibleSources Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:46 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 27 12:40:46 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:46 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:46 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:46 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:46 volumio volumio[858]: info: Listing playlists Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetQueue Apr 27 12:40:46 volumio volumio[858]: info: CoreStateMachine::getQueue Apr 27 12:40:46 volumio volumio[858]: info: CorePlayQueue::getQueue Apr 27 12:40:46 volumio go-librespot[2109]: time="2024-04-27T12:40:46+08:00" level=debug msg="completed challenge" Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 27 12:40:46 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:46 volumio go-librespot[2109]: time="2024-04-27T12:40:46+08:00" level=debug msg="new websocket client" Apr 27 12:40:46 volumio volumio[858]: info: Connection to go-librespot Websocket established Apr 27 12:40:46 volumio go-librespot[2109]: time="2024-04-27T12:40:46+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 27 12:40:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:40:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:40:46 volumio volumio[858]: info: Connection to go-librespot Websocket closed Apr 27 12:40:46 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:46 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:46 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:46 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:46 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:47 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:47 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:47 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:47 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::volumioGetVisibleSources Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:47 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 27 12:40:47 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:47 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:47 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:47 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:47 volumio volumio[858]: info: Listing playlists Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::volumioGetQueue Apr 27 12:40:47 volumio volumio[858]: info: CoreStateMachine::getQueue Apr 27 12:40:47 volumio volumio[858]: info: CorePlayQueue::getQueue Apr 27 12:40:47 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:47 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:47 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:47 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:47 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 27 12:40:48 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:48 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:48 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:48 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetVisibleSources Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:48 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 27 12:40:48 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:48 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:48 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:48 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:48 volumio volumio[858]: info: Listing playlists Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetQueue Apr 27 12:40:48 volumio volumio[858]: info: CoreStateMachine::getQueue Apr 27 12:40:48 volumio volumio[858]: info: CorePlayQueue::getQueue Apr 27 12:40:48 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:48 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:48 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:48 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 27 12:40:48 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:48 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:48 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:48 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:48 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetVisibleSources Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 27 12:40:49 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:49 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: Listing playlists Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetQueue Apr 27 12:40:49 volumio volumio[858]: info: CoreStateMachine::getQueue Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getQueue Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 27 12:40:49 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:49 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:49 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: Getting Spotify volume Apr 27 12:40:49 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:40:49 volumio volumio[858]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 27 12:40:49 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 22) Apr 27 12:40:49 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 12 Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:49 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 27 12:40:49 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:40:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30. Apr 27 12:40:49 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetVisibleSources Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 27 12:40:49 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:49 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:49 volumio volumio[858]: info: Listing playlists Apr 27 12:40:49 volumio volumio[858]: info: CoreCommandRouter::volumioGetQueue Apr 27 12:40:49 volumio volumio[858]: info: CoreStateMachine::getQueue Apr 27 12:40:49 volumio volumio[858]: info: CorePlayQueue::getQueue Apr 27 12:40:50 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:40:50 volumio go-librespot[2117]: Librespot-go daemon starting... Apr 27 12:40:50 volumio go-librespot[2117]: time="2024-04-27T12:40:50+08:00" level=info msg="generated new device id: 98032bf6e75053968e55efc762f51c14c55e65ff" Apr 27 12:40:50 volumio go-librespot[2117]: time="2024-04-27T12:40:50+08:00" level=debug msg="stored credentials not found" Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 27 12:40:50 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:50 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:50 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:50 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:50 volumio volumio[858]: info: Received Get System Info Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:40:50 volumio volumio[858]: info: Discovery: Getting this device information Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:50 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:40:50 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:50 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:50 volumio go-librespot[2117]: time="2024-04-27T12:40:50+08:00" level=debug msg="obtained new client token: AABofA0lOwgLWX/mKmZrsYl09rKuet9d7wrTINniUZg2TX7SHnVQ7jbP4v9qVioAS+B064LHRRCEo5cJ0kwAIIrW+xbraEvOQ21aBhCitoMS/ruYQxe1F+gDSYQR3N0jXvuH72hH++iWOSEiVjxttB3LmhoTKHAjUZ6CFYDSfvN7uA8tn+zqrJ1gEcwyIQR94dsKJ5Q05X2QOdix0CYdxYFVE27RDGqe7dsTjsGyXGuPL00zhJEuKqAI5fIGTB4=" Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 27 12:40:51 volumio volumio[858]: info: Retrieving Cloud Streaming UI Apr 27 12:40:51 volumio volumio[858]: info: Getting Tidal Cloud Configuration Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 27 12:40:51 volumio volumio[858]: info: Getting Qobuz Cloud Configuration Apr 27 12:40:51 volumio volumio[858]: info: Asking plugin for UI Config Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 27 12:40:51 volumio volumio[858]: info: Getting Spotify Cloud Configuration Apr 27 12:40:51 volumio volumio[858]: info: Asking plugin for UI Config Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 27 12:40:51 volumio volumio[858]: info: Saving Spotify Acccount Apr 27 12:40:51 volumio volumio[858]: info: Got Tidal Cloud Configuration Apr 27 12:40:51 volumio volumio[858]: info: Got it Apr 27 12:40:51 volumio volumio[858]: info: Got it Apr 27 12:40:51 volumio volumio[858]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 27 12:40:51 volumio volumio[858]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::volumioGetBrowseSources Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::volumioGetBrowseSources Apr 27 12:40:51 volumio volumio[858]: info: CoreCommandRouter::volumioGetBrowseSources Apr 27 12:40:51 volumio go-librespot[2117]: time="2024-04-27T12:40:51+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 27 12:40:51 volumio go-librespot[2117]: time="2024-04-27T12:40:51+08:00" level=debug msg="completed keyexchange" Apr 27 12:40:51 volumio go-librespot[2117]: time="2024-04-27T12:40:51+08:00" level=debug msg="completed challenge" Apr 27 12:40:52 volumio go-librespot[2117]: time="2024-04-27T12:40:52+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 27 12:40:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:40:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:40:52 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:52 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:40:53 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 27 12:40:53 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Apr 27 12:40:55 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:40:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31. Apr 27 12:40:55 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:40:55 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:40:55 volumio go-librespot[2129]: Librespot-go daemon starting... Apr 27 12:40:55 volumio go-librespot[2129]: time="2024-04-27T12:40:55+08:00" level=info msg="generated new device id: 53c1d7a151337c7cbd32efd057cbf43644cf725d" Apr 27 12:40:55 volumio go-librespot[2129]: time="2024-04-27T12:40:55+08:00" level=debug msg="stored credentials not found" Apr 27 12:40:55 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:40:55 volumio go-librespot[2129]: time="2024-04-27T12:40:55+08:00" level=debug msg="new websocket client" Apr 27 12:40:55 volumio volumio[858]: info: Connection to go-librespot Websocket established Apr 27 12:40:56 volumio go-librespot[2129]: time="2024-04-27T12:40:56+08:00" level=debug msg="obtained new client token: AAB3unpZjOJ2QdGpk/hL2dHAqp5yyUU7ZmqVQxj7IkF5skRRVnsiWYhfHpkz9+BhuAk8BvJdav6cus/+5Vv2JVixinmtBc+OrW9jku2f8rw6xm9YliIryMXvmvNH7cSlrvA4Fv3Kj3eHS95f5rqx2Z0sS+aPhZ4GDTxz1eiq+Xbr4e/Aog/VLoIMw60dK6MWQJBVuk9oWSx7AhJNV0pMDR4xa7Tk85k4FRPGi+VkImievRNy8ub/pH5FE7vAbfc=" Apr 27 12:40:56 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand update Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:56 volumio volumio[858]: info: Apr 27 12:40:56 volumio volumio[858]: ---------------------------- MPD announces state update: update Apr 27 12:40:56 volumio volumio[858]: info: sendMpdCommand update took 9 milliseconds Apr 27 12:40:56 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:56 volumio volumio[858]: info: sendMpdCommand status took 7 milliseconds Apr 27 12:40:56 volumio volumio[858]: info: sendMpdCommand status took 3 milliseconds Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:56 volumio go-librespot[2129]: time="2024-04-27T12:40:56+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 27 12:40:56 volumio volumio[858]: info: Command Router : Notfying DB Updatetrue Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:56 volumio volumio[858]: info: Apr 27 12:40:56 volumio volumio[858]: ---------------------------- MPD announces state update: update Apr 27 12:40:56 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:56 volumio volumio[858]: info: Apr 27 12:40:56 volumio volumio[858]: ---------------------------- MPD announces state update: update Apr 27 12:40:56 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:56 volumio volumio[858]: info: sendMpdCommand playlistinfo took 18 milliseconds Apr 27 12:40:56 volumio volumio[858]: info: sendMpdCommand status took 9 milliseconds Apr 27 12:40:56 volumio volumio[858]: info: sendMpdCommand status took 9 milliseconds Apr 27 12:40:56 volumio volumio[858]: info: sendMpdCommand status took 9 milliseconds Apr 27 12:40:56 volumio volumio[858]: info: sendMpdCommand status took 9 milliseconds Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:56 volumio go-librespot[2129]: time="2024-04-27T12:40:56+08:00" level=debug msg="completed keyexchange" Apr 27 12:40:56 volumio volumio[858]: info: Command Router : Notfying DB Updatetrue Apr 27 12:40:56 volumio volumio[858]: info: CoreCommandRouter::Close All Modals sent Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:56 volumio volumio[858]: info: Command Router : Notfying DB Updatetrue Apr 27 12:40:56 volumio volumio[858]: info: CoreCommandRouter::Close All Modals sent Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:56 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:40:56 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:40:56 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:40:56 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:56 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":3323,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","artist":null,"album":null,"uri":"USB/288016118015E65A/muse/Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","trackType":"ape"} Apr 27 12:40:56 volumio volumio[858]: verbose: CURRENT POSITION 0 Apr 27 12:40:56 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:40:56 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:40:56 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:40:56 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:56 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:40:56 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:40:56 volumio volumio[858]: info: ------------------------------ 255ms Apr 27 12:40:57 volumio volumio[858]: info: sendMpdCommand playlistinfo took 114 milliseconds Apr 27 12:40:57 volumio volumio[858]: info: sendMpdCommand playlistinfo took 77 milliseconds Apr 27 12:40:57 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:40:57 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:40:57 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:40:57 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:40:57 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:57 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":3323,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","artist":null,"album":null,"uri":"USB/288016118015E65A/muse/Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","trackType":"ape"} Apr 27 12:40:57 volumio volumio[858]: verbose: CURRENT POSITION 0 Apr 27 12:40:57 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:40:57 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:40:57 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:40:57 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:57 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:40:57 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:40:57 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:40:57 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:57 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":3323,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","artist":null,"album":null,"uri":"USB/288016118015E65A/muse/Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","trackType":"ape"} Apr 27 12:40:57 volumio volumio[858]: verbose: CURRENT POSITION 0 Apr 27 12:40:57 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:40:57 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:40:57 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:40:57 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:57 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:40:57 volumio volumio[858]: info: ------------------------------ 233ms Apr 27 12:40:57 volumio volumio[858]: info: ------------------------------ 232ms Apr 27 12:40:57 volumio go-librespot[2129]: time="2024-04-27T12:40:57+08:00" level=debug msg="completed challenge" Apr 27 12:40:57 volumio go-librespot[2129]: time="2024-04-27T12:40:57+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 27 12:40:57 volumio volumio[858]: info: Connection to go-librespot Websocket closed Apr 27 12:40:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:40:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:40:57 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , rescanDb Apr 27 12:40:57 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand rescan Apr 27 12:40:57 volumio volumio[858]: info: sendMpdCommand rescan took 4 milliseconds Apr 27 12:40:57 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand update Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand update took 5 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: MPD Database updated - AlbumList cache refreshed Apr 27 12:40:58 volumio volumio[858]: info: Apr 27 12:40:58 volumio volumio[858]: ---------------------------- MPD announces state update: database Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:58 volumio volumio[858]: info: Apr 27 12:40:58 volumio volumio[858]: ---------------------------- MPD announces state update: update Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:58 volumio volumio[858]: info: MPD Database updated - AlbumList cache refreshed Apr 27 12:40:58 volumio volumio[858]: info: Apr 27 12:40:58 volumio volumio[858]: ---------------------------- MPD announces state update: database Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:58 volumio volumio[858]: info: Apr 27 12:40:58 volumio volumio[858]: ---------------------------- MPD announces state update: update Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:58 volumio volumio[858]: info: MPD Database updated - AlbumList cache refreshed Apr 27 12:40:58 volumio volumio[858]: info: Apr 27 12:40:58 volumio volumio[858]: ---------------------------- MPD announces state update: database Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:58 volumio volumio[858]: info: Apr 27 12:40:58 volumio volumio[858]: ---------------------------- MPD announces state update: update Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand status took 55 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand status took 54 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand status took 54 milliseconds Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:58 volumio volumio[858]: info: Command Router : Notfying DB Updatetrue Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::Close All Modals sent Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand status took 169 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand status took 168 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand status took 167 milliseconds Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:58 volumio volumio[858]: info: Command Router : Notfying DB Updatetrue Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::Close All Modals sent Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand status took 294 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand status took 290 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand status took 288 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand playlistinfo took 172 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand playlistinfo took 168 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand playlistinfo took 68 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand playlistinfo took 69 milliseconds Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:58 volumio volumio[858]: info: Command Router : Notfying DB Updatetrue Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::Close All Modals sent Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":3323,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","artist":null,"album":null,"uri":"USB/288016118015E65A/muse/Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","trackType":"ape"} Apr 27 12:40:58 volumio volumio[858]: verbose: CURRENT POSITION 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":3323,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","artist":null,"album":null,"uri":"USB/288016118015E65A/muse/Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","trackType":"ape"} Apr 27 12:40:58 volumio volumio[858]: verbose: CURRENT POSITION 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":3323,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","artist":null,"album":null,"uri":"USB/288016118015E65A/muse/Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","trackType":"ape"} Apr 27 12:40:58 volumio volumio[858]: verbose: CURRENT POSITION 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":3323,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","artist":null,"album":null,"uri":"USB/288016118015E65A/muse/Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","trackType":"ape"} Apr 27 12:40:58 volumio volumio[858]: verbose: CURRENT POSITION 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:40:58 volumio volumio[858]: info: ------------------------------ 481ms Apr 27 12:40:58 volumio volumio[858]: info: ------------------------------ 480ms Apr 27 12:40:58 volumio volumio[858]: info: ------------------------------ 477ms Apr 27 12:40:58 volumio volumio[858]: info: ------------------------------ 477ms Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand playlistinfo took 113 milliseconds Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand playlistinfo took 113 milliseconds Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":3323,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","artist":null,"album":null,"uri":"USB/288016118015E65A/muse/Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","trackType":"ape"} Apr 27 12:40:58 volumio volumio[858]: verbose: CURRENT POSITION 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:40:58 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":3323,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","artist":null,"album":null,"uri":"USB/288016118015E65A/muse/Beyond.-.[Beyond.Live.1991演唱会CD2].专辑.(APE).ape","trackType":"ape"} Apr 27 12:40:58 volumio volumio[858]: verbose: CURRENT POSITION 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:40:58 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:40:58 volumio volumio[858]: info: ------------------------------ 534ms Apr 27 12:40:58 volumio volumio[858]: info: ------------------------------ 534ms Apr 27 12:40:58 volumio volumio[858]: info: Getting Spotify volume Apr 27 12:40:58 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:40:58 volumio volumio[858]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 27 12:40:58 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 23) Apr 27 12:40:58 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 12 Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:40:58 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Apr 27 12:40:58 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Apr 27 12:40:58 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand update Apr 27 12:40:58 volumio volumio[858]: info: sendMpdCommand update took 6 milliseconds Apr 27 12:40:59 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Apr 27 12:40:59 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand update Apr 27 12:40:59 volumio volumio[858]: info: sendMpdCommand update took 5 milliseconds Apr 27 12:41:00 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Apr 27 12:41:00 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand update Apr 27 12:41:00 volumio volumio[858]: info: sendMpdCommand update took 2 milliseconds Apr 27 12:41:00 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:00 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:41:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32. Apr 27 12:41:00 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:41:00 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:41:00 volumio go-librespot[2153]: Librespot-go daemon starting... Apr 27 12:41:00 volumio go-librespot[2153]: time="2024-04-27T12:41:00+08:00" level=info msg="generated new device id: fcdc25d7f114f31e5220dccb07696860db3e206c" Apr 27 12:41:00 volumio go-librespot[2153]: time="2024-04-27T12:41:00+08:00" level=debug msg="stored credentials not found" Apr 27 12:41:01 volumio go-librespot[2153]: time="2024-04-27T12:41:01+08:00" level=debug msg="obtained new client token: AABPD2IFNxci/f5hh9IOuCDCkJ26+FFEjPGCJf5MUOhSYRpVZpsWEZdfPkEAlbr/wdKN8h2CTXQ82UuP5FimY0v7onJr+Lx6bQSEw8LX3MS984UTwYfBTGt/HaVqBnocW28l8ZSuXs6d+L/ipmT5AFVh+2wchNAFdh5QTGjGINfqeFYUJOM1HPzRc1YzcUHQzr2Ba9NxgJ5pULnfdVLjOot67ZapJI5rcxXtOQGdAioD1mTBS9N/WDpO1jqEHgw=" Apr 27 12:41:01 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 27 12:41:02 volumio go-librespot[2153]: time="2024-04-27T12:41:02+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 27 12:41:02 volumio go-librespot[2153]: time="2024-04-27T12:41:02+08:00" level=debug msg="completed keyexchange" Apr 27 12:41:02 volumio go-librespot[2153]: time="2024-04-27T12:41:02+08:00" level=debug msg="completed challenge" Apr 27 12:41:02 volumio go-librespot[2153]: time="2024-04-27T12:41:02+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 27 12:41:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:41:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:41:03 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:03 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPlay Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::play index 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::stop Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::play index undefined Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::startPlaybackTimer Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::clearAddPlayTracks USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand stop Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand stop took 10 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand clear Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:04 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand status took 5 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand clear took 4 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand status took 3 milliseconds Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape" Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 27 12:41:04 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState stateService stop Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:04 volumio volumio[858]: info: No code Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 81ms Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:04 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:04 volumio volumio[858]: error: updateQueue error: null Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:04 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 85ms Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand playlistinfo took 82 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand add "USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape" took 82 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand status took 6 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 5ms Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand play Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:04 volumio volumio[858]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 27 12:41:04 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState stateService stop Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:04 volumio volumio[858]: info: No code Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 131ms Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 88ms Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:04 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:04 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 125ms Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand play took 119 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 40ms Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 5ms Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:04 volumio volumio[858]: info: Apr 27 12:41:04 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand status took 20 milliseconds Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand status took 20 milliseconds Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand status took 20 milliseconds Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand status took 40 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand clearerror took 28 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand clearerror took 26 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand clearerror took 22 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand playlistinfo took 14 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand playlistinfo took 14 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand playlistinfo took 14 milliseconds Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":255,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2002年的第一场雪","artist":"[www.51ape.com]刀郎","album":null,"uri":"USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape","trackType":"ape"} Apr 27 12:41:04 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":255,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2002年的第一场雪","artist":"[www.51ape.com]刀郎","album":null,"uri":"USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape","trackType":"ape"} Apr 27 12:41:04 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":255,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2002年的第一场雪","artist":"[www.51ape.com]刀郎","album":null,"uri":"USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape","trackType":"ape"} Apr 27 12:41:04 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 99ms Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 99ms Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 94ms Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand clearerror took 88 milliseconds Apr 27 12:41:04 volumio volumio[858]: info: sendMpdCommand playlistinfo took 87 milliseconds Apr 27 12:41:04 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:04 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":255,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2002年的第一场雪","artist":"[www.51ape.com]刀郎","album":null,"uri":"USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape","trackType":"ape"} Apr 27 12:41:04 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:04 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:04 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:41:04 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:04 volumio volumio[858]: info: ------------------------------ 151ms Apr 27 12:41:05 volumio volumio[858]: info: CoreCommandRouter::volumioPlay Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::play index 1 Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::stop Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::play index undefined Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:41:05 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::startPlaybackTimer Apr 27 12:41:05 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::clearAddPlayTracks USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand stop Apr 27 12:41:05 volumio volumio[858]: info: Apr 27 12:41:05 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:05 volumio volumio[858]: info: sendMpdCommand stop took 4 milliseconds Apr 27 12:41:05 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand clear Apr 27 12:41:05 volumio volumio[858]: info: Apr 27 12:41:05 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:05 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:05 volumio volumio[858]: info: Apr 27 12:41:05 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:05 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:05 volumio volumio[858]: info: Apr 27 12:41:05 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:05 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:05 volumio volumio[858]: info: sendMpdCommand status took 6 milliseconds Apr 27 12:41:05 volumio volumio[858]: info: sendMpdCommand clear took 6 milliseconds Apr 27 12:41:05 volumio volumio[858]: info: sendMpdCommand status took 4 milliseconds Apr 27 12:41:05 volumio volumio[858]: info: sendMpdCommand status took 3 milliseconds Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape" Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:05 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:05 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:05 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:05 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:41:05 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:05 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:05 volumio volumio[858]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 27 12:41:05 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::syncState stateService stop Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:05 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:05 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:05 volumio volumio[858]: info: No code Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:05 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:05 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:05 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:05 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:05 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:05 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:05 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:05 volumio volumio[858]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 27 12:41:05 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::syncState stateService stop Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:05 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:05 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:05 volumio volumio[858]: info: No code Apr 27 12:41:05 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:05 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:05 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:05 volumio volumio[858]: info: ------------------------------ 144ms Apr 27 12:41:05 volumio volumio[858]: info: ------------------------------ 142ms Apr 27 12:41:05 volumio volumio[858]: info: Apr 27 12:41:05 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:05 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:05 volumio volumio[858]: error: updateQueue error: null Apr 27 12:41:05 volumio volumio[858]: info: Apr 27 12:41:05 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:05 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:05 volumio volumio[858]: info: ------------------------------ 144ms Apr 27 12:41:05 volumio volumio[858]: info: sendMpdCommand playlistinfo took 143 milliseconds Apr 27 12:41:05 volumio volumio[858]: info: sendMpdCommand add "USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape" took 142 milliseconds Apr 27 12:41:05 volumio volumio[858]: info: ------------------------------ 3ms Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:05 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand play Apr 27 12:41:05 volumio volumio[858]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 27 12:41:05 volumio volumio[858]: info: ------------------------------ 153ms Apr 27 12:41:05 volumio volumio[858]: info: Apr 27 12:41:05 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:06 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:06 volumio volumio[858]: info: Apr 27 12:41:06 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:06 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:06 volumio volumio[858]: info: Apr 27 12:41:06 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:06 volumio volumio[858]: info: ------------------------------ 45ms Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand play took 42 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: ------------------------------ 42ms Apr 27 12:41:06 volumio volumio[858]: info: ------------------------------ 41ms Apr 27 12:41:06 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:06 volumio volumio[858]: info: Apr 27 12:41:06 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:06 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:06 volumio volumio[858]: info: Apr 27 12:41:06 volumio volumio[858]: ---------------------------- MPD announces system playlist update Apr 27 12:41:06 volumio volumio[858]: info: Ignoring MPD Status Update Apr 27 12:41:06 volumio volumio[858]: info: Apr 27 12:41:06 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand status took 61 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand status took 62 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: ------------------------------ 62ms Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:06 volumio volumio[858]: info: Apr 27 12:41:06 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:06 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:06 volumio volumio[858]: info: Apr 27 12:41:06 volumio volumio[858]: ---------------------------- MPD announces state update: player Apr 27 12:41:06 volumio volumio[858]: info: ControllerMpd::getState Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand clearerror took 19 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand status took 19 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand clearerror took 17 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand playlistinfo took 7 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand playlistinfo took 6 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand status took 5 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand status took 4 milliseconds Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::parseState Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:41:06 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:06 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:06 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":255,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2002年的第一场雪","artist":"[www.51ape.com]刀郎","album":null,"uri":"USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape","trackType":"ape"} Apr 27 12:41:06 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:06 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:06 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:06 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:06 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":255,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2002年的第一场雪","artist":"[www.51ape.com]刀郎","album":null,"uri":"USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape","trackType":"ape"} Apr 27 12:41:06 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:06 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:06 volumio volumio[858]: info: ------------------------------ 122ms Apr 27 12:41:06 volumio volumio[858]: info: ------------------------------ 120ms Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand playlistinfo took 55 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand playlistinfo took 53 milliseconds Apr 27 12:41:06 volumio volumio[858]: info: sendMpdCommand playlistinfo took 53 milliseconds Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:06 volumio volumio[858]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:41:06 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:06 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:06 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":255,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2002年的第一场雪","artist":"[www.51ape.com]刀郎","album":null,"uri":"USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape","trackType":"ape"} Apr 27 12:41:06 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:06 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:06 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:06 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:06 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":255,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2002年的第一场雪","artist":"[www.51ape.com]刀郎","album":null,"uri":"USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape","trackType":"ape"} Apr 27 12:41:06 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:06 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:06 volumio volumio[858]: info: ControllerMpd::pushState Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::servicePushState Apr 27 12:41:06 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:06 volumio volumio[858]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":255,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2002年的第一场雪","artist":"[www.51ape.com]刀郎","album":null,"uri":"USB/288016118015E65A/muse/刀郎-2002年的第一场雪.ape","trackType":"ape"} Apr 27 12:41:06 volumio volumio[858]: verbose: CURRENT POSITION 1 Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::syncState stateService pause Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:41:06 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:06 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:06 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:41:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 33. Apr 27 12:41:06 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:41:06 volumio volumio[858]: info: ------------------------------ 153ms Apr 27 12:41:06 volumio volumio[858]: info: ------------------------------ 126ms Apr 27 12:41:06 volumio volumio[858]: info: ------------------------------ 126ms Apr 27 12:41:06 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:41:06 volumio go-librespot[2161]: Librespot-go daemon starting... Apr 27 12:41:06 volumio go-librespot[2161]: time="2024-04-27T12:41:06+08:00" level=info msg="generated new device id: 097414b9000ca1932128605164a1a3fc44b6c734" Apr 27 12:41:06 volumio go-librespot[2161]: time="2024-04-27T12:41:06+08:00" level=debug msg="stored credentials not found" Apr 27 12:41:06 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:06 volumio go-librespot[2161]: time="2024-04-27T12:41:06+08:00" level=debug msg="new websocket client" Apr 27 12:41:06 volumio volumio[858]: info: Connection to go-librespot Websocket established Apr 27 12:41:07 volumio go-librespot[2161]: time="2024-04-27T12:41:07+08:00" level=debug msg="obtained new client token: AADWou8bzyyya0av1no3Epsx0vED06m9RDIju1OpUog5WHePo0pGJtNw7V6S1oWmN4tctzg8Ooa+J9XuIny7WQ1rYNCTMhfPCq/SfPTPRzRA6xT9vBvK2UFerARKtHOekWp4nHUXrWQ64vUs0VRzFifnlZjSd5dwtDYY722P6FGQOE6b5hgcErgJtxdtC6fbsHnFpsmCQT1k/eXV53LuBIDJyLbYAntTW8XglJbmzO5+N5yv7YBZaxK/EuaS" Apr 27 12:41:07 volumio go-librespot[2161]: time="2024-04-27T12:41: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 27 12:41:08 volumio go-librespot[2161]: time="2024-04-27T12:41:08+08:00" level=debug msg="completed keyexchange" Apr 27 12:41:08 volumio go-librespot[2161]: time="2024-04-27T12:41:08+08:00" level=debug msg="completed challenge" Apr 27 12:41:08 volumio go-librespot[2161]: time="2024-04-27T12:41: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 27 12:41:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:41:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:41:08 volumio volumio[858]: info: Connection to go-librespot Websocket closed Apr 27 12:41:09 volumio volumio[858]: info: Getting Spotify volume Apr 27 12:41:09 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:09 volumio volumio[858]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 27 12:41:09 volumio volumio[858]: (node:858) 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: 24) Apr 27 12:41:09 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 12 Apr 27 12:41:09 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:41:09 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:11 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:11 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:41:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34. Apr 27 12:41:11 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:41:11 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:41:11 volumio go-librespot[2210]: Librespot-go daemon starting... Apr 27 12:41:11 volumio go-librespot[2210]: time="2024-04-27T12:41:11+08:00" level=info msg="generated new device id: ece7e69617472e3520bf52bdf10e25bbc66fb3a5" Apr 27 12:41:11 volumio go-librespot[2210]: time="2024-04-27T12:41:11+08:00" level=debug msg="stored credentials not found" Apr 27 12:41:12 volumio go-librespot[2210]: time="2024-04-27T12:41:12+08:00" level=debug msg="obtained new client token: AABGNb2ei7DsQL+q33vSz4YLvp0orqls0Z2YDdjuKdBcKYHqCRUyH9EshWHfBnn9vpgS+xeHwVOyhUnDS2Gyco4vdZIVMGO3HPcHpsI+dqEzY+IuZHYe8bgraYK6kJefNDpVCOKczOyDl9xAh6NiX0MewxvY3UUIKwVyF9RC3TRZT03y3xb1/AV1iRXuv/Z2TXYs7v0vbJgjdG7zAI/P58Vd0xewui+cxa5c7dq89dXUi/lMt+PzHPtrL8RBYPA=" Apr 27 12:41:13 volumio go-librespot[2210]: time="2024-04-27T12:41: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-gew1.spotify.com:80]" Apr 27 12:41:13 volumio go-librespot[2210]: time="2024-04-27T12:41:13+08:00" level=debug msg="completed keyexchange" Apr 27 12:41:13 volumio go-librespot[2210]: time="2024-04-27T12:41:13+08:00" level=debug msg="completed challenge" Apr 27 12:41:14 volumio go-librespot[2210]: time="2024-04-27T12:41: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 27 12:41:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:41:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:41:14 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:14 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:41:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35. Apr 27 12:41:17 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:41:17 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:41:17 volumio go-librespot[2220]: Librespot-go daemon starting... Apr 27 12:41:17 volumio go-librespot[2220]: time="2024-04-27T12:41:17+08:00" level=info msg="generated new device id: 6e9276b34600760bda39988a952f7e61044eb2a5" Apr 27 12:41:17 volumio go-librespot[2220]: time="2024-04-27T12:41:17+08:00" level=debug msg="stored credentials not found" Apr 27 12:41:17 volumio volumio[858]: info: CoreCommandRouter::volumioRandom Apr 27 12:41:17 volumio volumio[858]: info: CoreCommandRouter::writePlayerControls Apr 27 12:41:17 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:17 volumio volumio[858]: info: CoreStateMachine::setRandom true Apr 27 12:41:17 volumio volumio[858]: info: CoreStateMachine::pushState Apr 27 12:41:17 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:17 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:41:17 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Apr 27 12:41:17 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:17 volumio go-librespot[2220]: time="2024-04-27T12:41:17+08:00" level=debug msg="new websocket client" Apr 27 12:41:17 volumio volumio[858]: info: Connection to go-librespot Websocket established Apr 27 12:41:18 volumio go-librespot[2220]: time="2024-04-27T12:41:18+08:00" level=debug msg="obtained new client token: AAC1GZ/S9B3G7ZidOngyV13Fs+0fJnNYU5zz813hH8pM22wPzW/iM/y2mVRjaRD8yl5LF0Uoafw2koWIcBRqugiBHJ7YgDC7c5CeFvLr8LmEioliJd9X5swal9zkr5ZI1lAIskaOZI0ONY1KZ0qQOGO3UMVF6u6lEfOLPxF4REdphjfkFhtPM2QVItRAA4Plbmh8zgAjK0xwqj4vSDUhoPbnxHTbXgLgnz1iulH23vtqq0CRHteeDk6j9xHz" Apr 27 12:41:19 volumio go-librespot[2220]: time="2024-04-27T12:41:19+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 27 12:41:19 volumio go-librespot[2220]: time="2024-04-27T12:41:19+08:00" level=debug msg="completed keyexchange" Apr 27 12:41:19 volumio go-librespot[2220]: time="2024-04-27T12:41:19+08:00" level=debug msg="completed challenge" Apr 27 12:41:19 volumio go-librespot[2220]: time="2024-04-27T12:41: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 27 12:41:19 volumio volumio[858]: info: Connection to go-librespot Websocket closed Apr 27 12:41:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:41:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:41:20 volumio volumio[858]: info: Getting Spotify volume Apr 27 12:41:20 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:20 volumio volumio[858]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 27 12:41:20 volumio volumio[858]: (node:858) 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: 25) Apr 27 12:41:20 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 12 Apr 27 12:41:20 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:41:20 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:22 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:22 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:22 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:41:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36. Apr 27 12:41:22 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:41:23 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:41:23 volumio go-librespot[2228]: Librespot-go daemon starting... Apr 27 12:41:23 volumio go-librespot[2228]: time="2024-04-27T12:41:23+08:00" level=info msg="generated new device id: b5d2c6b398b9179e88e4d21d0583c0a47295cf2a" Apr 27 12:41:23 volumio go-librespot[2228]: time="2024-04-27T12:41:23+08:00" level=debug msg="stored credentials not found" Apr 27 12:41:23 volumio go-librespot[2228]: time="2024-04-27T12:41:23+08:00" level=debug msg="obtained new client token: AACs0+VFxJBs7lgs5CCFTZAYbdKH/jrL+w56hf//cimaVkLLJw0O0I89d1gX1yUm0PgUVHvUC5CrXdBYs08U/jYsBTBlxgEKkeLFdVX0qemNYLeH5SAc8XTOXHfYnuE69tymHIix2KrNgomT3fXtCoYq6wK4OEKkReTxKKQOy+ZDsFxkLyPg9EoBBQ33WycKo3BtQb/mWxsmGOnRNbcZx4v8hQVhmRZXnQ6V+RlZ7SEuHci3Xxh5RHgyCdQgKYA=" Apr 27 12:41:24 volumio go-librespot[2228]: time="2024-04-27T12:41:24+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 27 12:41:24 volumio go-librespot[2228]: time="2024-04-27T12:41:24+08:00" level=debug msg="completed keyexchange" Apr 27 12:41:25 volumio go-librespot[2228]: time="2024-04-27T12:41:25+08:00" level=debug msg="completed challenge" Apr 27 12:41:25 volumio go-librespot[2228]: time="2024-04-27T12:41:25+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 27 12:41:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:41:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:41:25 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:25 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:28 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:41:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 37. Apr 27 12:41:28 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:41:28 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:41:28 volumio go-librespot[2236]: Librespot-go daemon starting... Apr 27 12:41:28 volumio go-librespot[2236]: time="2024-04-27T12:41:28+08:00" level=info msg="generated new device id: d335b9af7f6556685b13cabe23d5ecc3cacab424" Apr 27 12:41:28 volumio go-librespot[2236]: time="2024-04-27T12:41:28+08:00" level=debug msg="stored credentials not found" Apr 27 12:41:28 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:28 volumio go-librespot[2236]: time="2024-04-27T12:41:28+08:00" level=debug msg="new websocket client" Apr 27 12:41:28 volumio volumio[858]: info: Connection to go-librespot Websocket established Apr 27 12:41:29 volumio go-librespot[2236]: time="2024-04-27T12:41:29+08:00" level=debug msg="obtained new client token: AADIPJyrKa7b0CsfzCBhkYlK34ebSF38iq3VXCZgyJCHMh96xJONZXtqpITFjkxUXhQf12cGwiSL99R04VQuEaUpNYAuKetRxUgN22xBwLnBB13j/AJ0x5zaHUBhP42pg673YabmOjbffPigICuRB6dfOGlmElsvEjAUzkDgvlzFdrpoTePWClg3DSzT/yuZV4ZV2L3PgLqRAiOAeRAYOq0CoVMWJr5o8NGclj1TRSevGDEeCMD6nmqQbChsjig=" Apr 27 12:41:29 volumio go-librespot[2236]: time="2024-04-27T12:41:29+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 27 12:41:29 volumio go-librespot[2236]: time="2024-04-27T12:41:29+08:00" level=debug msg="completed keyexchange" Apr 27 12:41:30 volumio go-librespot[2236]: time="2024-04-27T12:41:30+08:00" level=debug msg="completed challenge" Apr 27 12:41:30 volumio go-librespot[2236]: time="2024-04-27T12:41:30+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 27 12:41:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:41:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:41:30 volumio volumio[858]: info: Connection to go-librespot Websocket closed Apr 27 12:41:31 volumio volumio[858]: info: Getting Spotify volume Apr 27 12:41:31 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:31 volumio volumio[858]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 27 12:41:31 volumio volumio[858]: (node:858) 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: 26) Apr 27 12:41:31 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 12 Apr 27 12:41:31 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:41:31 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:33 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:33 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:33 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:41:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 38. Apr 27 12:41:33 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:41:33 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:41:33 volumio go-librespot[2246]: Librespot-go daemon starting... Apr 27 12:41:33 volumio go-librespot[2246]: time="2024-04-27T12:41:33+08:00" level=info msg="generated new device id: e959c2466afe1a66feace921046fdfce1e6b9f60" Apr 27 12:41:33 volumio go-librespot[2246]: time="2024-04-27T12:41:33+08:00" level=debug msg="stored credentials not found" Apr 27 12:41:34 volumio go-librespot[2246]: time="2024-04-27T12:41:34+08:00" level=debug msg="obtained new client token: AAB2awqp2RStnDcJ5/4zN+yT38W9BuTCIhSn0JvQV5GrHjDPBgZg5RxEOLlOGVR2ppgNGEpKiLyjHiGlv9Mqz7BD34qudQ9mIitt3Tz0A/TyQx5ToYNYiix3uVw6tC/ePzbgKG1ymumrnXTOVBSRCnRvtHRzcIOzkds0KYpZLap2UCe9IhO+VibpdEtNjiZX4bmIyP9XpBFRqIuUDhTFA7T7umnUFWf1GIEoSldzX0PvPh+iLgLhla4AGuS/hBA=" Apr 27 12:41:35 volumio go-librespot[2246]: time="2024-04-27T12:41:35+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 27 12:41:36 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:36 volumio go-librespot[2246]: time="2024-04-27T12:41:36+08:00" level=debug msg="new websocket client" Apr 27 12:41:36 volumio volumio[858]: info: Connection to go-librespot Websocket established Apr 27 12:41:36 volumio go-librespot[2246]: time="2024-04-27T12:41:36+08:00" level=debug msg="completed keyexchange" Apr 27 12:41:37 volumio go-librespot[2246]: time="2024-04-27T12:41:37+08:00" level=debug msg="completed challenge" Apr 27 12:41:37 volumio go-librespot[2246]: time="2024-04-27T12:41:37+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 27 12:41:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 27 12:41:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 27 12:41:37 volumio volumio[858]: info: Connection to go-librespot Websocket closed Apr 27 12:41:39 volumio volumio[858]: info: Getting Spotify volume Apr 27 12:41:39 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:39 volumio volumio[858]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 27 12:41:39 volumio volumio[858]: (node:858) 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: 27) Apr 27 12:41:39 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 12 Apr 27 12:41:39 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Apr 27 12:41:39 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Apr 27 12:41:40 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Apr 27 12:41:40 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 27 12:41:40 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 27 12:41:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 39. Apr 27 12:41:40 volumio systemd[1]: Stopped go-librespot Daemon. Apr 27 12:41:40 volumio systemd[1]: Started go-librespot Daemon. Apr 27 12:41:40 volumio go-librespot[2254]: Librespot-go daemon starting... Apr 27 12:41:40 volumio go-librespot[2254]: time="2024-04-27T12:41:40+08:00" level=info msg="generated new device id: e0c20cea92c9c5bd3ae606987da30b08622f2ae9" Apr 27 12:41:40 volumio go-librespot[2254]: time="2024-04-27T12:41:40+08:00" level=debug msg="stored credentials not found" Apr 27 12:41:41 volumio volumio[858]: info: Preload queue cleared Apr 27 12:41:41 volumio volumio[858]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 27 12:41:41 volumio volumio[858]: info: CoreStateMachine::ClearQueue Apr 27 12:41:41 volumio volumio[858]: info: CoreStateMachine::stop Apr 27 12:41:41 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:41:41 volumio volumio[858]: info: CorePlayQueue::clearPlayQueue Apr 27 12:41:41 volumio volumio[858]: info: CorePlayQueue::saveQueue Apr 27 12:41:41 volumio volumio[858]: info: CoreCommandRouter::volumioPushQueue Apr 27 12:41:41 volumio volumio[858]: info: CoreStateMachine::addQueueItems Apr 27 12:41:41 volumio volumio[858]: info: CorePlayQueue::addQueueItems Apr 27 12:41:41 volumio volumio[858]: info: Preload queue cleared Apr 27 12:41:41 volumio volumio[858]: info: Adding Item to queue: music-library/USB/288016118015E65A/muse/孙露《声色扰人 BSCD》WAV Apr 27 12:41:41 volumio volumio[858]: info: Exploding uri music-library/USB/288016118015E65A/muse/孙露《声色扰人 BSCD》WAV in service mpd Apr 27 12:41:41 volumio volumio[858]: info: ALBUMART /albumart?cacheid=378&web=/%3F%3F%C9%AB%3F%3F%3F%3F%20BSCD/extralarge&path=%2Fmnt%2FUSB%2F288016118015E65A%2Fmuse%2F%E5%AD%99%E9%9C%B2%E3%80%8A%E5%A3%B0%E8%89%B2%E6%89%B0%E4%BA%BA%20BSCD%E3%80%8BWAV%2F%E5%AD%99%E9%9C%B2.cue&metadata=false Apr 27 12:41:41 volumio volumio[858]: info: URI /mnt/USB/288016118015E65A/muse/孙露《声色扰人 BSCD》WAV/孙露.cue Apr 27 12:41:41 volumio volumio[858]: info: ALBUMART /albumart?cacheid=378&web=/%3F%3F%C9%AB%3F%3F%3F%3F%20BSCD/extralarge&path=%2Fmnt%2FUSB%2F288016118015E65A%2Fmuse%2F%E5%AD%99%E9%9C%B2%E3%80%8A%E5%A3%B0%E8%89%B2%E6%89%B0%E4%BA%BA%20BSCD%E3%80%8BWAV%2F%E5%AD%99%E9%9C%B2.cue&metadata=false Apr 27 12:41:41 volumio volumio[858]: info: URI /mnt/USB/288016118015E65A/muse/孙露《声色扰人 BSCD》WAV/孙露.cue Apr 27 12:41:41 volumio volumio[858]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 27 12:41:41 volumio volumio[858]: Error: Unable to resolve or reject the same promise twice Apr 27 12:41:41 volumio volumio[858]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Apr 27 12:41:41 volumio volumio[858]: at /volumio/app/plugins/music_service/mpd/index.js:2568:21 Apr 27 12:41:41 volumio volumio[858]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Apr 27 12:41:41 volumio volumio[858]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Apr 27 12:41:41 volumio volumio[858]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Apr 27 12:41:41 volumio volumio[858]: at Socket.emit (events.js:315:20) Apr 27 12:41:41 volumio volumio[858]: at addChunk (internal/streams/readable.js:309:12) Apr 27 12:41:41 volumio volumio[858]: at readableAddChunk (internal/streams/readable.js:280:11) Apr 27 12:41:41 volumio volumio[858]: at Socket.Readable.push (internal/streams/readable.js:223:10) Apr 27 12:41:41 volumio volumio[858]: at Pipe.onStreamRead (internal/stream_base_commons.js:188:23) Apr 27 12:41:41 volumio volumio[858]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 27 12:41:41 volumio go-librespot[2254]: time="2024-04-27T12:41:41+08:00" level=debug msg="obtained new client token: AAATM6+rJ8XVnZcyNYAFmgVdHX2316jY2Bm+V2WIgJvbPQ3zVpbLpAy+rx7n01iWg6u2cagoz+Y7hBT3LoAb3OgS+wAb5WIeQ65ML075O1wdn0Yb4Xx8bODZFg+gwH+gvil1Hqv3lSDb6Iv2FGujnzZEt/chi+G7OSqW0o/yAHevQLCDnSKh+CAGfsp8zQIHEJGzU7UiVSShAXbLMY/Yc2TM1wy1qbdBS+hLp9Azrzpmc+HYFpRRocZqnjKTnEM=" Apr 27 12:41:41 volumio sudo[2271]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-27 12:40 Apr 27 12:41:41 volumio sudo[2271]: 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"