-- 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"