-- Logs begin at Tue 2024-07-09 19:08:03 CST, end at Tue 2024-08-20 13:50:00 CST. -- Aug 20 13:49:01 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:01 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:01 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:01 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:01 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:01 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 840. Aug 20 13:49:01 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:01 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:01 volumio1 go-librespot[13738]: Librespot-go daemon starting... Aug 20 13:49:01 volumio1 go-librespot[13738]: time="2024-08-20T13:49:01+08:00" level=info msg="generated new device id: 2a87931a6b32cd32fb3a6ca6ac0a0d2fa1b7299f" Aug 20 13:49:01 volumio1 go-librespot[13738]: time="2024-08-20T13:49:01+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:02 volumio1 go-librespot[13738]: time="2024-08-20T13:49:02+08:00" level=debug msg="obtained new client token: AAD52tchaj6tCiIIRSQW5hWLlSI8ksrjH6KT+Cj6mFZg8yPHd5CsMV7DOEue8s3Wx6p28nVVK/lqVFfW/6RZQqIK4urXpzLHzSVQoP+yzjDSko9jk+9oru4rNLTkwP172Z7ig3K1hA1OO7p3Ov9GzlzdE8hLCLEMcc2WzX+dD1vBZESZj+vm0/1O1mXMK1GlM8ztdDz1BoF47N63UApjEdNFbqRXYfalalInqzoYiil4BVhAw4sP6lj1CEY=" Aug 20 13:49:02 volumio1 go-librespot[13738]: time="2024-08-20T13:49:02+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 20 13:49:02 volumio1 go-librespot[13738]: time="2024-08-20T13:49:02+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:02 volumio1 go-librespot[13738]: time="2024-08-20T13:49:02+08:00" level=debug msg="completed challenge" Aug 20 13:49:02 volumio1 go-librespot[13738]: time="2024-08-20T13:49:02+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:02 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:02 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:02 volumio1 volumio[1134]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Aug 20 13:49:02 volumio1 volumio[1134]: info: Retrying Login Due to Network Error Aug 20 13:49:03 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:03 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:04 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:04 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:05 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:05 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:06 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:06 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 841. Aug 20 13:49:06 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:06 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:06 volumio1 go-librespot[13755]: Librespot-go daemon starting... Aug 20 13:49:06 volumio1 go-librespot[13755]: time="2024-08-20T13:49:06+08:00" level=info msg="generated new device id: a8bfa81eb9a2decfe06b85c8629d78419774da66" Aug 20 13:49:06 volumio1 go-librespot[13755]: time="2024-08-20T13:49:06+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:06 volumio1 go-librespot[13755]: time="2024-08-20T13:49:06+08:00" level=debug msg="obtained new client token: AAARgXLQ1+5nFCGTtzq5D69jD0nYrwQwUCkyPoP1x+UIuy2gJW+d4TT2uWPuz0r2JyATDeapqO8kYt6i6kp6p+v7u8JcVKbksjgjf/9nsVSSqboVmzxvGpTrEsDKGxCIbuP6lheqhgVkEjz5wmRuqarXJVvGgORrYin03215BTMLPD/f5qX3oDEDkNU0gbvRv0OThxsMHW8wAbbdYtuSdcqTqVdKc9VH+rSVFGzz7IknmWM4QvOCsBGfsTvV+w==" Aug 20 13:49:06 volumio1 go-librespot[13755]: time="2024-08-20T13:49:06+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 20 13:49:06 volumio1 go-librespot[13755]: time="2024-08-20T13:49:06+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:07 volumio1 go-librespot[13755]: time="2024-08-20T13:49:07+08:00" level=debug msg="completed challenge" Aug 20 13:49:07 volumio1 go-librespot[13755]: time="2024-08-20T13:49:07+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:07 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:07 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:07 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:07 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:07 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:07 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:09 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:09 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:10 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:10 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 842. Aug 20 13:49:10 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:10 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:10 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:10 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:10 volumio1 go-librespot[13774]: Librespot-go daemon starting... Aug 20 13:49:10 volumio1 go-librespot[13774]: time="2024-08-20T13:49:10+08:00" level=info msg="generated new device id: ee3b822c088f9b575f6417d1a27278932421b626" Aug 20 13:49:10 volumio1 go-librespot[13774]: time="2024-08-20T13:49:10+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:11 volumio1 go-librespot[13774]: time="2024-08-20T13:49:11+08:00" level=debug msg="obtained new client token: AAAYCkips/3bmgsOTMWGPYQPfEr0DMQ9yF3OKnveDrAOGhII8wuUegk8YFUgJxccVaM9uU0tpgEm1zy/6cEXC0RUzrk5DvWrNSH+MPAKpUMIk3FsA1YwgM2Tme/EL92eYZWXNimo/MMLpDdWx8XDdxaHAGqwoQIz4Rv3Pg6ZnRs+Ixr1OoVDc/TXEOiFeKl8/P/11isp4EYix0fmByChWKU7cEx0/Yb6PkQp8nVGRCic4Db7POPvd+xuOuY=" Aug 20 13:49:11 volumio1 go-librespot[13774]: time="2024-08-20T13:49:11+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 20 13:49:11 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:11 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:11 volumio1 go-librespot[13774]: time="2024-08-20T13:49:11+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:12 volumio1 go-librespot[13774]: time="2024-08-20T13:49:12+08:00" level=debug msg="completed challenge" Aug 20 13:49:12 volumio1 go-librespot[13774]: time="2024-08-20T13:49:12+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:12 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:12 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:12 volumio1 volumio[1134]: info: MyVolumio login type: Token Aug 20 13:49:13 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:13 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:13 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:13 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:15 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:15 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:15 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:15 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 843. Aug 20 13:49:15 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:15 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:15 volumio1 go-librespot[13790]: Librespot-go daemon starting... Aug 20 13:49:15 volumio1 go-librespot[13790]: time="2024-08-20T13:49:15+08:00" level=info msg="generated new device id: da4deeebe6e7b81f9cbdaa51949675dc08173e88" Aug 20 13:49:15 volumio1 go-librespot[13790]: time="2024-08-20T13:49:15+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:16 volumio1 go-librespot[13790]: time="2024-08-20T13:49:16+08:00" level=debug msg="obtained new client token: AACMwJcgWKc35Z6OkVkRpwrGun4xlolYOm0MZiVh8r6x1lLLgvJeMv6gQ+PnRV7B7YZ/kIJwyk3uAAClZKICtK+3pry88L/BBFzP+YRZK1D7C2ztLnbgotjKjEisrOIM0N+AwD8sh27NhkC5kdg0ecox9/GFxdAa8Py3UxmqcnLof06Q5lASVIEB2WongjE/NBtAGJJcRyZSGaPffvS8Bnc5001DPsSMBtM0lMMSGRInMpT50Tsh3Ep0EZc=" Aug 20 13:49:16 volumio1 go-librespot[13790]: time="2024-08-20T13:49:16+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 20 13:49:16 volumio1 go-librespot[13790]: time="2024-08-20T13:49:16+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:16 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:16 volumio1 go-librespot[13790]: time="2024-08-20T13:49:16+08:00" level=debug msg="new websocket client" Aug 20 13:49:16 volumio1 volumio[1134]: info: Connection to go-librespot Websocket established Aug 20 13:49:17 volumio1 go-librespot[13790]: time="2024-08-20T13:49:17+08:00" level=debug msg="completed challenge" Aug 20 13:49:17 volumio1 go-librespot[13790]: time="2024-08-20T13:49:17+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:17 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:17 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:17 volumio1 volumio[1134]: info: Connection to go-librespot Websocket closed Aug 20 13:49:17 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:17 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:19 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:19 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:19 volumio1 volumio[1134]: info: Getting Spotify volume Aug 20 13:49:19 volumio1 volumio[1134]: (node:1134) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:19 volumio1 volumio[1134]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 20 13:49:19 volumio1 volumio[1134]: (node:1134) 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: 370) Aug 20 13:49:19 volumio1 volumio[1134]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Aug 20 13:49:19 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:19 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:19 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:20 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:20 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:20 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:20 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 844. Aug 20 13:49:20 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:20 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:20 volumio1 go-librespot[13809]: Librespot-go daemon starting... Aug 20 13:49:20 volumio1 go-librespot[13809]: time="2024-08-20T13:49:20+08:00" level=info msg="generated new device id: 90950c4728f3f2193d9ae4fb0555bd278cc40913" Aug 20 13:49:20 volumio1 go-librespot[13809]: time="2024-08-20T13:49:20+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:20 volumio1 go-librespot[13809]: time="2024-08-20T13:49:20+08:00" level=debug msg="obtained new client token: AAD1XAiUPAwOFZrNYu1uwDXQvGXEpirBMEG4fco8LcP0sOnkNpy4JsuDolwL+NuZGwV4z+yKVeYt0aLcyiaQZLeIrODQPV6ByGPgAVb7rL0jBSXX81gH6b/lB/s0BLbMoFdjCPMwq6QFR9Cc3736epnVxJFnQx6Q7HxEDw3z5Cr64Jj6eCqOpVy+WWKGsCap6LnPVQoPLuP4/0GNW7cvQYLGDwSj7RRZ7s9hIC7bqbe0j3yyhidaUmZ8mgj9nA==" Aug 20 13:49:20 volumio1 go-librespot[13809]: time="2024-08-20T13:49:20+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]" Aug 20 13:49:21 volumio1 go-librespot[13809]: time="2024-08-20T13:49:21+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:21 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:21 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:21 volumio1 go-librespot[13809]: time="2024-08-20T13:49:21+08:00" level=debug msg="completed challenge" Aug 20 13:49:21 volumio1 go-librespot[13809]: time="2024-08-20T13:49:21+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:21 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:21 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:23 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:23 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:23 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:23 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:24 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:24 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 845. Aug 20 13:49:24 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:24 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:24 volumio1 go-librespot[13827]: Librespot-go daemon starting... Aug 20 13:49:24 volumio1 go-librespot[13827]: time="2024-08-20T13:49:24+08:00" level=info msg="generated new device id: c6916aa044188ab2ca7917ca856ea662dff38e65" Aug 20 13:49:24 volumio1 go-librespot[13827]: time="2024-08-20T13:49:24+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:25 volumio1 go-librespot[13827]: time="2024-08-20T13:49:25+08:00" level=debug msg="obtained new client token: AABVwPr7qA8F8JgKfUOdhC/abjzJMiDiP31h/1rO/uvRo5CC0aq+DuSGh8WZHEN0SnXWvEVlOWi4jvKe/pYK0SKKiYqsGMydMSZLjj8VoSe8h5RFGgDqS2zGUz4AmtchOoII4OPC725OQDsfcykAkW5s89goS6Bbc/VJ5Gn9X2Pv2j+drAcMXC5/vmGLfdCWbH46voGeEfe7Z4FFH/IPhSTNdurGJ0QmfgdEtQiM58gm0eYStg9kbOV2VbLTnQ==" Aug 20 13:49:25 volumio1 go-librespot[13827]: time="2024-08-20T13:49:25+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 20 13:49:25 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:25 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:25 volumio1 go-librespot[13827]: time="2024-08-20T13:49:25+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:26 volumio1 go-librespot[13827]: time="2024-08-20T13:49:26+08:00" level=debug msg="completed challenge" Aug 20 13:49:26 volumio1 go-librespot[13827]: time="2024-08-20T13:49:26+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:26 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:26 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:26 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:26 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:27 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:27 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:29 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:29 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:29 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:29 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 846. Aug 20 13:49:29 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:29 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:29 volumio1 go-librespot[13844]: Librespot-go daemon starting... Aug 20 13:49:29 volumio1 go-librespot[13844]: time="2024-08-20T13:49:29+08:00" level=info msg="generated new device id: 1d55afe1ae38f8e076cfe5b89c04cd78cb8c492a" Aug 20 13:49:29 volumio1 go-librespot[13844]: time="2024-08-20T13:49:29+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:29 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:29 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:29 volumio1 go-librespot[13844]: time="2024-08-20T13:49:29+08:00" level=debug msg="obtained new client token: AAA5s/9xTO7+DcXuPIhps9NTsg/344VJTnb77NnF8ZlZ+JUgl4AtZV6/+kKR74hwFq/EubdCb8/hxUAkjCVsMf123MtGbhxPpMdDTqy/qAXzbIIaO2ijHBeWzXftIePssWbKtZIKBKvr2RZ0j5gEgciOQ1I9IgfmHzDTE2uq8X2/9wpGemm3uA0J2I5ndK2ZIo7z2zVzKsricsCzzq0h8D+QImaH/0x91GnVx3xbPpXPmpp9B+2IFm3vjNJTFw==" Aug 20 13:49:29 volumio1 go-librespot[13844]: time="2024-08-20T13:49: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 20 13:49:30 volumio1 go-librespot[13844]: time="2024-08-20T13:49:30+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:30 volumio1 go-librespot[13844]: time="2024-08-20T13:49:30+08:00" level=debug msg="completed challenge" Aug 20 13:49:31 volumio1 go-librespot[13844]: time="2024-08-20T13:49:31+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:31 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:31 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:31 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:31 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:32 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:32 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:33 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:33 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:34 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:34 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 847. Aug 20 13:49:34 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:34 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:34 volumio1 go-librespot[13903]: Librespot-go daemon starting... Aug 20 13:49:34 volumio1 go-librespot[13903]: time="2024-08-20T13:49:34+08:00" level=info msg="generated new device id: 1197f8d4681b360ee1589febcb97b61604f0de0f" Aug 20 13:49:34 volumio1 go-librespot[13903]: time="2024-08-20T13:49:34+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:34 volumio1 go-librespot[13903]: time="2024-08-20T13:49:34+08:00" level=debug msg="obtained new client token: AACxGQSmREawCZlwOuUtfqxcBKEc8XEREivJ7RuS6/xPiSSYKb412QsvQIvKCYc1z0zfyQQ1zaON58yZ3P7D0an8jxcQHWldVWJmdUrjLIR0IyGhGvLEenJGe5xephdFzr4d6V1dLKTULlagNL2UHyIBt4xKV0mKFuNsIYJJYrB0gSR1TL31MLEt6M3zGad+EPFClQEbMDQh1UI0NBcyWg0CehUiaRHCgP01H3TP2eF3KHB8g1NmJ1MIKyORXA==" Aug 20 13:49:34 volumio1 go-librespot[13903]: time="2024-08-20T13:49:34+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 20 13:49:35 volumio1 go-librespot[13903]: time="2024-08-20T13:49:35+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:35 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:35 volumio1 go-librespot[13903]: time="2024-08-20T13:49:35+08:00" level=debug msg="new websocket client" Aug 20 13:49:35 volumio1 volumio[1134]: info: Connection to go-librespot Websocket established Aug 20 13:49:35 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:35 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:35 volumio1 go-librespot[13903]: time="2024-08-20T13:49:35+08:00" level=debug msg="completed challenge" Aug 20 13:49:35 volumio1 go-librespot[13903]: time="2024-08-20T13:49:35+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:35 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:35 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:35 volumio1 volumio[1134]: info: Connection to go-librespot Websocket closed Aug 20 13:49:37 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:37 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:38 volumio1 volumio[1134]: info: Getting Spotify volume Aug 20 13:49:38 volumio1 volumio[1134]: (node:1134) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:38 volumio1 volumio[1134]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 20 13:49:38 volumio1 volumio[1134]: (node:1134) 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: 371) Aug 20 13:49:38 volumio1 volumio[1134]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Aug 20 13:49:38 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:38 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:38 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:38 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:38 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:38 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:38 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 848. Aug 20 13:49:38 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:38 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:38 volumio1 go-librespot[13919]: Librespot-go daemon starting... Aug 20 13:49:38 volumio1 go-librespot[13919]: time="2024-08-20T13:49:38+08:00" level=info msg="generated new device id: ff4f09ffbfd197cb8eb5d6099d54f4eca7d9c119" Aug 20 13:49:38 volumio1 go-librespot[13919]: time="2024-08-20T13:49:38+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:39 volumio1 go-librespot[13919]: time="2024-08-20T13:49:39+08:00" level=debug msg="obtained new client token: AAB/plG1dcLGzL4NoD93Z08Z3H9zw+0Ulbz8sA5azqfzzY+nAhXY4gIxqGpOc6E2xxEywfeoFmpKPjukNq+WC8I3QrigWf3xobKoBtVyn6OK18ooOlP3ampf8LIP0JmyZHwQTRSUlnh1Wweo7/87W0gJy69oSgXF3Bw09YHz165wK9Ww5ejUqc7IKXC5gIs2mUg64O3W7ErdArFJ8XTKv9PxVRhRlNG9P6Bnz0r+AufURIArnuShHanXjaY=" Aug 20 13:49:39 volumio1 go-librespot[13919]: time="2024-08-20T13:49: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]" Aug 20 13:49:39 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:39 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:39 volumio1 go-librespot[13919]: time="2024-08-20T13:49:39+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:40 volumio1 go-librespot[13919]: time="2024-08-20T13:49:40+08:00" level=debug msg="completed challenge" Aug 20 13:49:40 volumio1 go-librespot[13919]: time="2024-08-20T13:49:40+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:40 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:40 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:41 volumio1 volumio[1134]: info: Prefetching next song Aug 20 13:49:41 volumio1 volumio[1134]: info: DOING PREFETCH IN MPD Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand add "USB/900B-7EA1/2024/赵鹏-船歌.flac" Aug 20 13:49:41 volumio1 volumio[1134]: info: Aug 20 13:49:41 volumio1 volumio[1134]: ---------------------------- MPD announces system playlist update Aug 20 13:49:41 volumio1 volumio[1134]: info: Ignoring MPD Status Update Aug 20 13:49:41 volumio1 volumio[1134]: info: sendMpdCommand add "USB/900B-7EA1/2024/赵鹏-船歌.flac" took 3 milliseconds Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand consume 1 Aug 20 13:49:41 volumio1 volumio[1134]: info: Aug 20 13:49:41 volumio1 volumio[1134]: ---------------------------- MPD announces system playlist update Aug 20 13:49:41 volumio1 volumio[1134]: info: Ignoring MPD Status Update Aug 20 13:49:41 volumio1 volumio[1134]: info: Aug 20 13:49:41 volumio1 volumio[1134]: ---------------------------- MPD announces system playlist update Aug 20 13:49:41 volumio1 volumio[1134]: info: Ignoring MPD Status Update Aug 20 13:49:41 volumio1 volumio[1134]: info: Aug 20 13:49:41 volumio1 volumio[1134]: ---------------------------- MPD announces system playlist update Aug 20 13:49:41 volumio1 volumio[1134]: info: Ignoring MPD Status Update Aug 20 13:49:41 volumio1 volumio[1134]: info: Aug 20 13:49:41 volumio1 volumio[1134]: ---------------------------- MPD announces state update: options Aug 20 13:49:41 volumio1 volumio[1134]: info: ------------------------------ 16ms Aug 20 13:49:41 volumio1 volumio[1134]: info: sendMpdCommand consume 1 took 15 milliseconds Aug 20 13:49:41 volumio1 volumio[1134]: info: ControllerMpd::getState Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand status Aug 20 13:49:41 volumio1 volumio[1134]: info: ------------------------------ 14ms Aug 20 13:49:41 volumio1 volumio[1134]: info: ------------------------------ 11ms Aug 20 13:49:41 volumio1 volumio[1134]: info: ------------------------------ 9ms Aug 20 13:49:41 volumio1 volumio[1134]: info: Aug 20 13:49:41 volumio1 volumio[1134]: ---------------------------- MPD announces state update: options Aug 20 13:49:41 volumio1 volumio[1134]: info: ControllerMpd::getState Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand status Aug 20 13:49:41 volumio1 volumio[1134]: info: Aug 20 13:49:41 volumio1 volumio[1134]: ---------------------------- MPD announces state update: options Aug 20 13:49:41 volumio1 volumio[1134]: info: ControllerMpd::getState Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand status Aug 20 13:49:41 volumio1 volumio[1134]: info: Aug 20 13:49:41 volumio1 volumio[1134]: ---------------------------- MPD announces state update: options Aug 20 13:49:41 volumio1 volumio[1134]: info: ControllerMpd::getState Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand status Aug 20 13:49:41 volumio1 volumio[1134]: info: sendMpdCommand status took 13 milliseconds Aug 20 13:49:41 volumio1 volumio[1134]: info: sendMpdCommand status took 10 milliseconds Aug 20 13:49:41 volumio1 volumio[1134]: info: sendMpdCommand status took 9 milliseconds Aug 20 13:49:41 volumio1 volumio[1134]: info: sendMpdCommand status took 6 milliseconds Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::parseState Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::parseState Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::parseState Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::parseState Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 20 13:49:41 volumio1 volumio[1134]: info: sendMpdCommand playlistinfo took 15 milliseconds Aug 20 13:49:41 volumio1 volumio[1134]: info: sendMpdCommand playlistinfo took 15 milliseconds Aug 20 13:49:41 volumio1 volumio[1134]: info: sendMpdCommand playlistinfo took 8 milliseconds Aug 20 13:49:41 volumio1 volumio[1134]: info: sendMpdCommand playlistinfo took 8 milliseconds Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::parseTrackInfo Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::parseTrackInfo Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::parseTrackInfo Aug 20 13:49:41 volumio1 volumio[1134]: verbose: ControllerMpd::parseTrackInfo Aug 20 13:49:41 volumio1 volumio[1134]: info: ControllerMpd::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::servicePushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: verbose: STATE SERVICE {"status":"play","position":0,"seek":113323,"duration":118,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"453 Kbps","isStreaming":false,"title":"Fear","artist":"FreshmanSound","album":"Time (Original Motion Picture Soundtrack)","uri":"USB/900B-7EA1/2024/FreshmanSound-Fear.flac","trackType":"flac"} Aug 20 13:49:41 volumio1 volumio[1134]: verbose: CURRENT POSITION 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::syncState stateService play Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::syncState currentStatus play Aug 20 13:49:41 volumio1 volumio[1134]: info: Received an update from plugin. extracting info from payload Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:41 volumio1 volumio[1134]: info: ControllerMpd::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::servicePushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: verbose: STATE SERVICE {"status":"play","position":0,"seek":113323,"duration":118,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"453 Kbps","isStreaming":false,"title":"Fear","artist":"FreshmanSound","album":"Time (Original Motion Picture Soundtrack)","uri":"USB/900B-7EA1/2024/FreshmanSound-Fear.flac","trackType":"flac"} Aug 20 13:49:41 volumio1 volumio[1134]: verbose: CURRENT POSITION 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::syncState stateService play Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::syncState currentStatus play Aug 20 13:49:41 volumio1 volumio[1134]: info: Received an update from plugin. extracting info from payload Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:41 volumio1 volumio[1134]: info: ControllerMpd::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::servicePushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: verbose: STATE SERVICE {"status":"play","position":0,"seek":113323,"duration":118,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"453 Kbps","isStreaming":false,"title":"Fear","artist":"FreshmanSound","album":"Time (Original Motion Picture Soundtrack)","uri":"USB/900B-7EA1/2024/FreshmanSound-Fear.flac","trackType":"flac"} Aug 20 13:49:41 volumio1 volumio[1134]: verbose: CURRENT POSITION 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::syncState stateService play Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::syncState currentStatus play Aug 20 13:49:41 volumio1 volumio[1134]: info: Received an update from plugin. extracting info from payload Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:41 volumio1 volumio[1134]: info: ControllerMpd::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::servicePushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: verbose: STATE SERVICE {"status":"play","position":0,"seek":113461,"duration":118,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"455 Kbps","isStreaming":false,"title":"Fear","artist":"FreshmanSound","album":"Time (Original Motion Picture Soundtrack)","uri":"USB/900B-7EA1/2024/FreshmanSound-Fear.flac","trackType":"flac"} Aug 20 13:49:41 volumio1 volumio[1134]: verbose: CURRENT POSITION 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::syncState stateService play Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::syncState currentStatus play Aug 20 13:49:41 volumio1 volumio[1134]: info: Received an update from plugin. extracting info from payload Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:41 volumio1 volumio[1134]: info: ------------------------------ 111ms Aug 20 13:49:41 volumio1 volumio[1134]: info: ------------------------------ 106ms Aug 20 13:49:41 volumio1 volumio[1134]: info: ------------------------------ 104ms Aug 20 13:49:41 volumio1 volumio[1134]: info: ------------------------------ 102ms Aug 20 13:49:41 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:41 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:41 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:41 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:41 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:41 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:41 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:41 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:41 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:41 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:41 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:41 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:42 volumio1 volumio[1134]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Aug 20 13:49:42 volumio1 volumio[1134]: info: Retrying Login Due to Network Error Aug 20 13:49:43 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:43 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 849. Aug 20 13:49:43 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:43 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:43 volumio1 go-librespot[13942]: Librespot-go daemon starting... Aug 20 13:49:43 volumio1 go-librespot[13942]: time="2024-08-20T13:49:43+08:00" level=info msg="generated new device id: 7f3bc1c0d979a937ba33d2179594565a01cd69c6" Aug 20 13:49:43 volumio1 go-librespot[13942]: time="2024-08-20T13:49:43+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:43 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:43 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:43 volumio1 go-librespot[13942]: time="2024-08-20T13:49:43+08:00" level=debug msg="obtained new client token: AACwnFImccoRGS1SieZnFKZOHK+WcUkoLjAXEMJc5TTFGfMK7ZEeMeS0NsboXsJv2cjJlRvIje8R6PWHkaXkYWCv9diBjcgvZL59lRyD+IMbyzY+T8fzu4uODqZ6kzBi5iLIOFVCrzYFLhgfyLFnaCIufBJTI0uRt8BN1o1x0cuv2CtYlvZKMpkp3Ir6e4IHGPm0vszvr07NoBL5eltcbEZmo1NcYbdetYT7Df+D+gLOMSVEHun4sSdcr+46Ig==" Aug 20 13:49:43 volumio1 go-librespot[13942]: time="2024-08-20T13:49:43+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]" Aug 20 13:49:44 volumio1 go-librespot[13942]: time="2024-08-20T13:49:44+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:44 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:44 volumio1 go-librespot[13942]: time="2024-08-20T13:49:44+08:00" level=debug msg="new websocket client" Aug 20 13:49:44 volumio1 volumio[1134]: info: Connection to go-librespot Websocket established Aug 20 13:49:44 volumio1 go-librespot[13942]: time="2024-08-20T13:49:44+08:00" level=debug msg="completed challenge" Aug 20 13:49:45 volumio1 go-librespot[13942]: time="2024-08-20T13:49:45+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:45 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:45 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:45 volumio1 volumio[1134]: info: Connection to go-librespot Websocket closed Aug 20 13:49:45 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:45 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 4 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::startPlaybackTimer Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: Aug 20 13:49:46 volumio1 volumio[1134]: ---------------------------- MPD announces system playlist update Aug 20 13:49:46 volumio1 volumio[1134]: info: Ignoring MPD Status Update Aug 20 13:49:46 volumio1 volumio[1134]: info: Aug 20 13:49:46 volumio1 volumio[1134]: ---------------------------- MPD announces state update: player Aug 20 13:49:46 volumio1 volumio[1134]: info: ControllerMpd::getState Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand status Aug 20 13:49:46 volumio1 volumio[1134]: info: Aug 20 13:49:46 volumio1 volumio[1134]: ---------------------------- MPD announces system playlist update Aug 20 13:49:46 volumio1 volumio[1134]: info: Ignoring MPD Status Update Aug 20 13:49:46 volumio1 volumio[1134]: info: Aug 20 13:49:46 volumio1 volumio[1134]: ---------------------------- MPD announces state update: player Aug 20 13:49:46 volumio1 volumio[1134]: info: ControllerMpd::getState Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand status Aug 20 13:49:46 volumio1 volumio[1134]: info: Aug 20 13:49:46 volumio1 volumio[1134]: ---------------------------- MPD announces system playlist update Aug 20 13:49:46 volumio1 volumio[1134]: info: Ignoring MPD Status Update Aug 20 13:49:46 volumio1 volumio[1134]: info: Aug 20 13:49:46 volumio1 volumio[1134]: ---------------------------- MPD announces state update: player Aug 20 13:49:46 volumio1 volumio[1134]: info: ControllerMpd::getState Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand status Aug 20 13:49:46 volumio1 volumio[1134]: info: Aug 20 13:49:46 volumio1 volumio[1134]: ---------------------------- MPD announces system playlist update Aug 20 13:49:46 volumio1 volumio[1134]: info: Ignoring MPD Status Update Aug 20 13:49:46 volumio1 volumio[1134]: info: Aug 20 13:49:46 volumio1 volumio[1134]: ---------------------------- MPD announces state update: player Aug 20 13:49:46 volumio1 volumio[1134]: info: ControllerMpd::getState Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand status Aug 20 13:49:46 volumio1 volumio[1134]: info: ------------------------------ 19ms Aug 20 13:49:46 volumio1 volumio[1134]: info: sendMpdCommand status took 17 milliseconds Aug 20 13:49:46 volumio1 volumio[1134]: info: ------------------------------ 16ms Aug 20 13:49:46 volumio1 volumio[1134]: info: sendMpdCommand status took 11 milliseconds Aug 20 13:49:46 volumio1 volumio[1134]: info: ------------------------------ 9ms Aug 20 13:49:46 volumio1 volumio[1134]: info: sendMpdCommand status took 9 milliseconds Aug 20 13:49:46 volumio1 volumio[1134]: info: ------------------------------ 7ms Aug 20 13:49:46 volumio1 volumio[1134]: info: sendMpdCommand status took 7 milliseconds Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::parseState Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::parseState Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::parseState Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::parseState Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 20 13:49:46 volumio1 volumio[1134]: info: sendMpdCommand playlistinfo took 4 milliseconds Aug 20 13:49:46 volumio1 volumio[1134]: info: sendMpdCommand playlistinfo took 5 milliseconds Aug 20 13:49:46 volumio1 volumio[1134]: info: sendMpdCommand playlistinfo took 5 milliseconds Aug 20 13:49:46 volumio1 volumio[1134]: info: sendMpdCommand playlistinfo took 6 milliseconds Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::parseTrackInfo Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::parseTrackInfo Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::parseTrackInfo Aug 20 13:49:46 volumio1 volumio[1134]: verbose: ControllerMpd::parseTrackInfo Aug 20 13:49:46 volumio1 volumio[1134]: info: ControllerMpd::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::servicePushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":263,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"620 Kbps","isStreaming":false,"title":"船歌","artist":"赵鹏","album":"人声低音炮1-闪亮的日子","uri":"USB/900B-7EA1/2024/赵鹏-船歌.flac","trackType":"flac"} Aug 20 13:49:46 volumio1 volumio[1134]: verbose: CURRENT POSITION 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::syncState stateService play Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::syncState currentStatus play Aug 20 13:49:46 volumio1 volumio[1134]: info: Received an update from plugin. extracting info from payload Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:46 volumio1 volumio[1134]: info: ControllerMpd::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::servicePushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":263,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"620 Kbps","isStreaming":false,"title":"船歌","artist":"赵鹏","album":"人声低音炮1-闪亮的日子","uri":"USB/900B-7EA1/2024/赵鹏-船歌.flac","trackType":"flac"} Aug 20 13:49:46 volumio1 volumio[1134]: verbose: CURRENT POSITION 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::syncState stateService play Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::syncState currentStatus play Aug 20 13:49:46 volumio1 volumio[1134]: info: Received an update from plugin. extracting info from payload Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:46 volumio1 volumio[1134]: info: ControllerMpd::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::servicePushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":263,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"620 Kbps","isStreaming":false,"title":"船歌","artist":"赵鹏","album":"人声低音炮1-闪亮的日子","uri":"USB/900B-7EA1/2024/赵鹏-船歌.flac","trackType":"flac"} Aug 20 13:49:46 volumio1 volumio[1134]: verbose: CURRENT POSITION 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::syncState stateService play Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::syncState currentStatus play Aug 20 13:49:46 volumio1 volumio[1134]: info: Received an update from plugin. extracting info from payload Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:46 volumio1 volumio[1134]: info: ControllerMpd::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::servicePushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":263,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"620 Kbps","isStreaming":false,"title":"船歌","artist":"赵鹏","album":"人声低音炮1-闪亮的日子","uri":"USB/900B-7EA1/2024/赵鹏-船歌.flac","trackType":"flac"} Aug 20 13:49:46 volumio1 volumio[1134]: verbose: CURRENT POSITION 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::syncState stateService play Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::syncState currentStatus play Aug 20 13:49:46 volumio1 volumio[1134]: info: Received an update from plugin. extracting info from payload Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:46 volumio1 volumio[1134]: info: ------------------------------ 92ms Aug 20 13:49:46 volumio1 volumio[1134]: info: ------------------------------ 87ms Aug 20 13:49:46 volumio1 volumio[1134]: info: ------------------------------ 85ms Aug 20 13:49:46 volumio1 volumio[1134]: info: ------------------------------ 83ms Aug 20 13:49:46 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:46 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:46 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:46 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:46 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:46 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:46 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:46 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreStateMachine::pushState Aug 20 13:49:46 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 20 13:49:46 volumio1 volumio[1134]: info: CoreCommandRouter::volumioPushState Aug 20 13:49:46 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:47 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:47 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:47 volumio1 volumio[1134]: info: Getting Spotify volume Aug 20 13:49:47 volumio1 volumio[1134]: (node:1134) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:47 volumio1 volumio[1134]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 20 13:49:47 volumio1 volumio[1134]: (node:1134) 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: 372) Aug 20 13:49:47 volumio1 volumio[1134]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Aug 20 13:49:47 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:47 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:47 volumio1 volumio[1134]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Aug 20 13:49:48 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:48 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:48 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:48 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 850. Aug 20 13:49:48 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:48 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:48 volumio1 go-librespot[13961]: Librespot-go daemon starting... Aug 20 13:49:48 volumio1 go-librespot[13961]: time="2024-08-20T13:49:48+08:00" level=info msg="generated new device id: c2d899669d34fa80d93f1fd9ca892f38437710ba" Aug 20 13:49:48 volumio1 go-librespot[13961]: time="2024-08-20T13:49:48+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:48 volumio1 go-librespot[13961]: time="2024-08-20T13:49:48+08:00" level=debug msg="obtained new client token: AABJacLdka2w9Oj5jHPa0yR70TzoPkaasmK4qRzbdiSuXz+TYsBho+p3olYtXjFaVo53+3wwtzZRYyqzozl+84kPBG3LtKW5g6EfDKGzcg0Zf04jxdmRSS/l3y5D/+WVnakfSJKJjQCNMeogE373ldaiRh53fRgy2hg0xxQP0LaiqD2rCR+mZLLlQ/nQZCP3EZlME6QYMnpm3d6H2HcTXsZYkqqXyAhsze7zju10U5vZHHBj3pI/4FIlA1WbbQ==" Aug 20 13:49:48 volumio1 go-librespot[13961]: time="2024-08-20T13:49:48+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 20 13:49:48 volumio1 go-librespot[13961]: time="2024-08-20T13:49:48+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:49 volumio1 go-librespot[13961]: time="2024-08-20T13:49:49+08:00" level=debug msg="completed challenge" Aug 20 13:49:49 volumio1 go-librespot[13961]: time="2024-08-20T13:49:49+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:49 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:49 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:49 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:49 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:51 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:51 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:51 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:51 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:52 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:52 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 851. Aug 20 13:49:52 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:52 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:52 volumio1 go-librespot[13979]: Librespot-go daemon starting... Aug 20 13:49:52 volumio1 go-librespot[13979]: time="2024-08-20T13:49:52+08:00" level=info msg="generated new device id: f2d8a2816bfbcd69f0e0b4c9adc8bd4a42a41a4e" Aug 20 13:49:52 volumio1 go-librespot[13979]: time="2024-08-20T13:49:52+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:52 volumio1 volumio[1134]: info: MyVolumio login type: Token Aug 20 13:49:53 volumio1 go-librespot[13979]: time="2024-08-20T13:49:53+08:00" level=debug msg="obtained new client token: AADxv3ba1j2wOgY29Xmd/ha17eA6EGTdIw1sRPD5pGdbi0YawiLha7963gNVMzAQTy2QRzsNfk7Jzx65fIUrf3Y48lDLb4C5mxNg1OaOSPdsL4zHFSSt6ngZBEWAJZGyYXjVSBKPqWHPsXtBe/lCLe64K8hhAZgtAaDxlOgZYBL2uzcPgMOVtYnNHFwZ5omIMpAlUhk+jXQ4Jcqnm/XMupnwKuCAxLTjmOUdsFdcVSZtkkuV2hcCbA4GkUE=" Aug 20 13:49:53 volumio1 go-librespot[13979]: time="2024-08-20T13:49:53+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 20 13:49:53 volumio1 go-librespot[13979]: time="2024-08-20T13:49:53+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:53 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:53 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:53 volumio1 go-librespot[13979]: time="2024-08-20T13:49:53+08:00" level=debug msg="completed challenge" Aug 20 13:49:53 volumio1 go-librespot[13979]: time="2024-08-20T13:49:53+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:53 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:53 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:54 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:54 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:55 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:55 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:57 volumio1 volumio[1134]: info: Initializing connection to go-librespot Websocket Aug 20 13:49:57 volumio1 volumio[1134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 20 13:49:57 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 20 13:49:57 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 852. Aug 20 13:49:57 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 20 13:49:57 volumio1 systemd[1]: Started go-librespot Daemon. Aug 20 13:49:57 volumio1 go-librespot[13995]: Librespot-go daemon starting... Aug 20 13:49:57 volumio1 go-librespot[13995]: time="2024-08-20T13:49:57+08:00" level=info msg="generated new device id: 88fc89239ced50bacae612651a42c89c1befd201" Aug 20 13:49:57 volumio1 go-librespot[13995]: time="2024-08-20T13:49:57+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 20 13:49:57 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:57 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:57 volumio1 go-librespot[13995]: time="2024-08-20T13:49:57+08:00" level=debug msg="obtained new client token: AAAJ3jDcIf53DZy/0ZHxlr+ecDo/+bvI8SOxv6eZpDDppEL7K51fp8QQNYfta8LzKs+zOx5Ule423KJXtyb66wLlKuC7I9JvYr82CoFrZVL/fSNoZ0xpWpJIPYh8GrEjfx29F9EbFPF4vnnHf+zh5SOt0IplxeznrqQQBsYl+bSOlHVps9O9uRtJ8bPfgpLPctqjykX+E5U5dC0+Rq8PjWyeRH1p0/qCPGwsIeCRRfo3JZKEYsCe6Q/Oh6gO7g==" Aug 20 13:49:57 volumio1 go-librespot[13995]: time="2024-08-20T13:49:57+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]" Aug 20 13:49:58 volumio1 go-librespot[13995]: time="2024-08-20T13:49:58+08:00" level=debug msg="completed keyexchange" Aug 20 13:49:58 volumio1 go-librespot[13995]: time="2024-08-20T13:49:58+08:00" level=debug msg="completed challenge" Aug 20 13:49:58 volumio1 go-librespot[13995]: time="2024-08-20T13:49:58+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 20 13:49:58 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 20 13:49:58 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 20 13:49:59 volumio1 volumio[1134]: info: CoreCommandRouter::volumioGetState Aug 20 13:49:59 volumio1 volumio[1134]: info: CorePlayQueue::getTrack 5 Aug 20 13:49:59 volumio1 volumio[1134]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 20 13:49:59 volumio1 volumio[1134]: Error: connect ETIMEDOUT 104.244.43.57:443 Aug 20 13:49:59 volumio1 volumio[1134]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Aug 20 13:49:59 volumio1 volumio[1134]: errno: -110, Aug 20 13:49:59 volumio1 volumio[1134]: code: 'ETIMEDOUT', Aug 20 13:49:59 volumio1 volumio[1134]: syscall: 'connect', Aug 20 13:49:59 volumio1 volumio[1134]: address: '104.244.43.57', Aug 20 13:49:59 volumio1 volumio[1134]: port: 443 Aug 20 13:49:59 volumio1 volumio[1134]: } Aug 20 13:49:59 volumio1 volumio[1134]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 20 13:50:00 volumio1 sudo[14018]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-20 13:49 Aug 20 13:50:00 volumio1 sudo[14018]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="6e682b9410d28f3874f90b2d7789db824a859264" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="7c81f20187867c3bd55475ead0f12800fe93082c" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 08 Jun 2024 10:32:20 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="orangepipc" VOLUMIO_DEVICENAME="Orange Pi PC" VOLUMIO_HASH="85fabbf1ff267d6584c35638894541bf"