-- Logs begin at Thu 2019-02-14 19:11:59 KST, end at Mon 2024-05-06 11:02:36 KST. -- May 06 11:01:01 volumio volumio[881]: info: Getting Spotify volume May 06 11:01:01 volumio volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:01 volumio volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 06 11:01:01 volumio volumio[881]: (node:881) 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: 119) May 06 11:01:01 volumio volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 May 06 11:01:01 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:01:01 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:01 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:01 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 213. May 06 11:01:01 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:01 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:01 volumio go-librespot[5324]: Librespot-go daemon starting... May 06 11:01:01 volumio go-librespot[5324]: time="2024-05-06T11:01:01+09:00" level=info msg="generated new device id: 2a27edd37dd7c50ded636d286db621bf2efde465" May 06 11:01:01 volumio go-librespot[5324]: time="2024-05-06T11:01:01+09:00" level=debug msg="stored credentials not found" May 06 11:01:02 volumio go-librespot[5324]: time="2024-05-06T11:01:02+09:00" level=debug msg="obtained new client token: AADCKSyeeq+CjOKO5Fi+mC/67arbUTLjc0jNyTpatat5n4z/18CKxI5M23VMDhE7Mbq5t7ma9ElGiX40Nk7otfycKOnwmwN14HlV41dNUoKvLnvcIArM7HwUV7Z4RaRtn1+T4FS6rG1/uokqxbvZGt3s79EF5pzu8Pi9eAqt0SuP5meQPIJZ8f+NLhX4sDLpBKk8P+/h66i/CM0dicjYHEcWnaBHF+CJR+16cFRVI2i0pwVGDK/yVCuhQp8uGQ==" May 06 11:01:03 volumio go-librespot[5324]: time="2024-05-06T11:01:03+09: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]" May 06 11:01:03 volumio go-librespot[5324]: time="2024-05-06T11:01:03+09:00" level=debug msg="completed keyexchange" May 06 11:01:04 volumio go-librespot[5324]: time="2024-05-06T11:01:04+09:00" level=debug msg="completed challenge" May 06 11:01:04 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:04 volumio go-librespot[5324]: time="2024-05-06T11:01:04+09:00" level=debug msg="new websocket client" May 06 11:01:04 volumio volumio[881]: info: Connection to go-librespot Websocket established May 06 11:01:04 volumio go-librespot[5324]: time="2024-05-06T11:01:04+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:04 volumio volumio[881]: info: Connection to go-librespot Websocket closed May 06 11:01:07 volumio volumio[881]: info: Getting Spotify volume May 06 11:01:07 volumio volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:07 volumio volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 06 11:01:07 volumio volumio[881]: (node:881) 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: 120) May 06 11:01:07 volumio volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 May 06 11:01:07 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:01:07 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:07 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:07 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:07 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 214. May 06 11:01:07 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:07 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:07 volumio go-librespot[5332]: Librespot-go daemon starting... May 06 11:01:07 volumio go-librespot[5332]: time="2024-05-06T11:01:07+09:00" level=info msg="generated new device id: 06b2d263b1528306e28609c1116738beb9ea3363" May 06 11:01:07 volumio go-librespot[5332]: time="2024-05-06T11:01:07+09:00" level=debug msg="stored credentials not found" May 06 11:01:08 volumio go-librespot[5332]: time="2024-05-06T11:01:08+09:00" level=debug msg="obtained new client token: AACDfPFCjmNP2fhcZjmQnOK8bxKW5WXwHHbpGjzeqkTJ+pAFwLgHfm2ZcLaM+NDTpj5xLcZuP2bCkqRgcD54uY9AJ+PYZJ4o1/OlhrH5IfV5rLW4+M8tQUacvlcgO6E/KzovxNQY5UayXptqynIkzz+L/iXGgp9zyCmkccDLAA+P0vMVSeXgZDXhlpNM5N2b3VRerN5g5XxA7JsJQ3WyrLcuVUJ4Ldhg73DzkNo3TADiFysvFWnxjo2SbKxSOQ==" May 06 11:01:08 volumio go-librespot[5332]: time="2024-05-06T11:01:08+09: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]" May 06 11:01:09 volumio go-librespot[5332]: time="2024-05-06T11:01:09+09:00" level=debug msg="completed keyexchange" May 06 11:01:09 volumio go-librespot[5332]: time="2024-05-06T11:01:09+09:00" level=debug msg="completed challenge" May 06 11:01:09 volumio go-librespot[5332]: time="2024-05-06T11:01:09+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:10 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:10 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:12 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 215. May 06 11:01:12 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:12 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:12 volumio go-librespot[5341]: Librespot-go daemon starting... May 06 11:01:12 volumio go-librespot[5341]: time="2024-05-06T11:01:12+09:00" level=info msg="generated new device id: 960d262807f1ff6a072bac8ec25d7dc2a376a374" May 06 11:01:12 volumio go-librespot[5341]: time="2024-05-06T11:01:12+09:00" level=debug msg="stored credentials not found" May 06 11:01:13 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:13 volumio volumio[881]: info: Connection to go-librespot Websocket established May 06 11:01:13 volumio go-librespot[5341]: time="2024-05-06T11:01:13+09:00" level=debug msg="new websocket client" May 06 11:01:13 volumio go-librespot[5341]: time="2024-05-06T11:01:13+09:00" level=debug msg="obtained new client token: AABUOluONZ4F6JupqV43J1st+nMQX1h0gkOzTnbdan18eJhIxfb4kAUDquI/j1EiqrTEyjJ2dqacJoN53ndkOJCSl6TZ/a4UQ4+qrv/qEtr2W+MVyL0XCXJyywvdwWLPuvP9PUXve0OaRvnQ+tZfmJxzQjaUih+8LZBVLf98zxYDKfaH3c56OjjLpjozb0A47vYGPRbUHJdtj7UAdDaqozNaKXmpx7Ajv9fgaQvEyaVPVzV5zoOZ5t5sck0KtA==" May 06 11:01:14 volumio go-librespot[5341]: time="2024-05-06T11:01:14+09: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]" May 06 11:01:14 volumio go-librespot[5341]: time="2024-05-06T11:01:14+09:00" level=debug msg="completed keyexchange" May 06 11:01:14 volumio go-librespot[5341]: time="2024-05-06T11:01:14+09:00" level=debug msg="completed challenge" May 06 11:01:14 volumio go-librespot[5341]: time="2024-05-06T11:01:14+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:14 volumio volumio[881]: info: Connection to go-librespot Websocket closed May 06 11:01:16 volumio volumio[881]: info: Getting Spotify volume May 06 11:01:16 volumio volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:16 volumio volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 06 11:01:16 volumio volumio[881]: (node:881) 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: 121) May 06 11:01:16 volumio volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 May 06 11:01:16 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:01:16 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:17 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:17 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 216. May 06 11:01:17 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:17 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:17 volumio go-librespot[5349]: Librespot-go daemon starting... May 06 11:01:17 volumio go-librespot[5349]: time="2024-05-06T11:01:17+09:00" level=info msg="generated new device id: c7d62ae3a4ff44e091fd96998a09652dc992c823" May 06 11:01:17 volumio go-librespot[5349]: time="2024-05-06T11:01:17+09:00" level=debug msg="stored credentials not found" May 06 11:01:18 volumio go-librespot[5349]: time="2024-05-06T11:01:18+09:00" level=debug msg="obtained new client token: AACxw8feoCZuvw5OBdOFEOR4ysw02yB86rW+sJ2W5M3KlVA/bII+w+i5OYBO5poeQQklP5CKrEG/4JUyr+tKw/yyR3dmgExYXrP+ZCBbQ1m5XFEGTWbEJ++SoFnaE2TTyJ/R0SKMPLWFsIWRfP/afKfuMeIpfJ/ZLxYMbTG8rTlu3R2tXRefEWRhdmqkqwdZzlvSHhgT0GZMVedMqQAsctGGjnjKRXlrjJRj+er3hzBh9sLlQZtyLGcnjWHqwg==" May 06 11:01:19 volumio go-librespot[5349]: time="2024-05-06T11:01:19+09: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]" May 06 11:01:19 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:01:19 volumio go-librespot[5349]: time="2024-05-06T11:01:19+09:00" level=debug msg="completed keyexchange" May 06 11:01:19 volumio go-librespot[5349]: time="2024-05-06T11:01:19+09:00" level=debug msg="completed challenge" May 06 11:01:19 volumio go-librespot[5349]: time="2024-05-06T11:01:19+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:20 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:20 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 217. May 06 11:01:23 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:23 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:23 volumio go-librespot[5357]: Librespot-go daemon starting... May 06 11:01:23 volumio go-librespot[5357]: time="2024-05-06T11:01:23+09:00" level=info msg="generated new device id: d82daf15b97ad0ad671f4f16d1b1958be9b9384c" May 06 11:01:23 volumio go-librespot[5357]: time="2024-05-06T11:01:23+09:00" level=debug msg="stored credentials not found" May 06 11:01:23 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:23 volumio go-librespot[5357]: time="2024-05-06T11:01:23+09:00" level=debug msg="new websocket client" May 06 11:01:23 volumio volumio[881]: info: Connection to go-librespot Websocket established May 06 11:01:24 volumio go-librespot[5357]: time="2024-05-06T11:01:24+09:00" level=debug msg="obtained new client token: AACVXA5LdwkvGy5Gip54afryI+3EL09X7xoP8bypsof+Hr2lwezEpBviEEBwVES6rS5ixaq4n9l9/mtOe5XQcawro5BBxuf1wJujok2ARIgtN4eIeGIr459lqD7ULtGxIblWqYAa72eSMdAAghAva9Mir960IvG8v6zS2TSJoAhZn6OwIP2MgDV6IqekpdEYmjiVTjvriFQp6+WrrT72bLIUHpeKitF/Xq58n8AH0vckEFUzKlKjr7z+UTLVmA==" May 06 11:01:24 volumio go-librespot[5357]: time="2024-05-06T11:01:24+09: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]" May 06 11:01:24 volumio go-librespot[5357]: time="2024-05-06T11:01:24+09:00" level=debug msg="completed keyexchange" May 06 11:01:25 volumio go-librespot[5357]: time="2024-05-06T11:01:25+09:00" level=debug msg="completed challenge" May 06 11:01:25 volumio go-librespot[5357]: time="2024-05-06T11:01:25+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:25 volumio volumio[881]: info: Connection to go-librespot Websocket closed May 06 11:01:26 volumio volumio[881]: info: Getting Spotify volume May 06 11:01:26 volumio volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:26 volumio volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 06 11:01:26 volumio volumio[881]: (node:881) 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: 122) May 06 11:01:26 volumio volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 May 06 11:01:26 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:01:26 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:28 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:28 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:28 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 218. May 06 11:01:28 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:28 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:28 volumio go-librespot[5367]: Librespot-go daemon starting... May 06 11:01:28 volumio go-librespot[5367]: time="2024-05-06T11:01:28+09:00" level=info msg="generated new device id: fde1d70feadb3085d165f0aecb2e816384ba93ef" May 06 11:01:28 volumio go-librespot[5367]: time="2024-05-06T11:01:28+09:00" level=debug msg="stored credentials not found" May 06 11:01:29 volumio go-librespot[5367]: time="2024-05-06T11:01:29+09:00" level=debug msg="obtained new client token: AACfgElsV9WCOPVwlVen2kzUtYQkk7dBH73EJytKldydp1UhBsQfzApSh6TkDGnNgRTN+8n97vAAwoUeZaEK5yX5JBPvcjCSoLmDPZEfriRuoiqmT5AIuf7yORHNKbdmIF5iqTWzfEiR25AqiVkg4zMQ0GGq1HQmlW1tWqxp9cc/kHjf6RCly4Z2eLtNtGgnoBRaVW0Pt3jq23+am8j09qKDrV9wFHdnnsStv8lYhz0KGTczpkvE9JIV2kU=" May 06 11:01:30 volumio go-librespot[5367]: time="2024-05-06T11:01:30+09: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]" May 06 11:01:30 volumio go-librespot[5367]: time="2024-05-06T11:01:30+09:00" level=debug msg="completed keyexchange" May 06 11:01:31 volumio go-librespot[5367]: time="2024-05-06T11:01:31+09:00" level=debug msg="completed challenge" May 06 11:01:31 volumio go-librespot[5367]: time="2024-05-06T11:01:31+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:31 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:31 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:32 volumio volumio[881]: info: Clearing queue after UPNP request May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::ClearQueue May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::stop May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::setConsumeUpdateService undefined May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::stPlaybackTimer May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::updateTrackBlock May 06 11:01:33 volumio volumio[881]: info: CorePlayQueue::getTrackBlock May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::pushState May 06 11:01:33 volumio volumio[881]: info: CorePlayQueue::getTrack 0 May 06 11:01:33 volumio volumio[881]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 06 11:01:33 volumio volumio[881]: info: CoreCommandRouter::volumioPushState May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::serviceStop May 06 11:01:33 volumio volumio[881]: info: CorePlayQueue::getTrack 0 May 06 11:01:33 volumio volumio[881]: info: ControllerMpd::stop May 06 11:01:33 volumio volumio[881]: verbose: ControllerMpd::sendMpdCommand stop May 06 11:01:33 volumio volumio[881]: info: CorePlayQueue::clearPlayQueue May 06 11:01:33 volumio volumio[881]: info: CorePlayQueue::saveQueue May 06 11:01:33 volumio volumio[881]: info: CoreCommandRouter::volumioPushState May 06 11:01:33 volumio volumio[881]: info: CoreCommandRouter::volumioPushQueue May 06 11:01:33 volumio volumio[881]: error: Upnp client error: Error: This socket has been ended by the other party May 06 11:01:33 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:33 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:33 volumio volumio[881]: info: May 06 11:01:33 volumio volumio[881]: ---------------------------- MPD announces state update: player May 06 11:01:33 volumio volumio[881]: info: sendMpdCommand stop took 66 milliseconds May 06 11:01:33 volumio volumio[881]: info: ControllerMpd::getState May 06 11:01:33 volumio volumio[881]: verbose: ControllerMpd::sendMpdCommand status May 06 11:01:33 volumio volumio[881]: info: sendMpdCommand status took 14 milliseconds May 06 11:01:33 volumio volumio[881]: verbose: ControllerMpd::parseState May 06 11:01:33 volumio volumio[881]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 06 11:01:33 volumio volumio[881]: info: sendMpdCommand playlistinfo took 6 milliseconds May 06 11:01:33 volumio volumio[881]: verbose: ControllerMpd::parseTrackInfo May 06 11:01:33 volumio volumio[881]: info: ControllerMpd::pushState May 06 11:01:33 volumio volumio[881]: info: CoreCommandRouter::servicePushState May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::pushState May 06 11:01:33 volumio volumio[881]: info: CorePlayQueue::getTrack 0 May 06 11:01:33 volumio volumio[881]: info: CoreCommandRouter::volumioPushState May 06 11:01:33 volumio volumio[881]: info: CorePlayQueue::getTrack 0 May 06 11:01:33 volumio volumio[881]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"いとしのエリー","artist":"サザンオールスターズ","album":"海のyeah!!","uri":"http://116.31.99.15/amobile.music.tc.qq.com/M5000047vkMC400XVN.mp3?guid=9599595CFC404289B2663212CFD7CA29&vkey=E7890A7FE24274A8E46BEF694348F3EABEC6BECBDBF383AA88FCE847295215B2ADA5601CF240CEBEF33E0A13A02015DEE007D87BE5631F41&uin=1182014284&redirect=1&fromtag=101042","trackType":""} May 06 11:01:33 volumio volumio[881]: verbose: CURRENT POSITION 0 May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::syncState stateService stop May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::syncState currentStatus stop May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::pushState May 06 11:01:33 volumio volumio[881]: info: CorePlayQueue::getTrack 0 May 06 11:01:33 volumio volumio[881]: info: CoreCommandRouter::volumioPushState May 06 11:01:33 volumio volumio[881]: info: No code May 06 11:01:33 volumio volumio[881]: info: CoreStateMachine::pushState May 06 11:01:33 volumio volumio[881]: info: CorePlayQueue::getTrack 0 May 06 11:01:33 volumio volumio[881]: info: CoreCommandRouter::volumioPushState May 06 11:01:33 volumio volumio[881]: info: ------------------------------ 75ms May 06 11:01:33 volumio volumio[881]: info: touch_display: Setting screensaver timeout to 15 seconds. May 06 11:01:33 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:33 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:33 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:34 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:34 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:34 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 219. May 06 11:01:34 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:34 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:34 volumio go-librespot[5379]: Librespot-go daemon starting... May 06 11:01:34 volumio go-librespot[5379]: time="2024-05-06T11:01:34+09:00" level=info msg="generated new device id: 9c05c6f053e3903c89f2c6d8a5413e47bf2e9e52" May 06 11:01:34 volumio go-librespot[5379]: time="2024-05-06T11:01:34+09:00" level=debug msg="stored credentials not found" May 06 11:01:34 volumio volumio[881]: info: Starting UPNP Playback May 06 11:01:34 volumio volumio[881]: info: Preparing playback through UPNP May 06 11:01:34 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:01:34 volumio volumio[881]: info: CorePlayQueue::getTrack 0 May 06 11:01:34 volumio volumio[881]: info: CoreStateMachine::setConsumeUpdateService mpd May 06 11:01:35 volumio go-librespot[5379]: time="2024-05-06T11:01:35+09:00" level=debug msg="obtained new client token: AAApjxuh8nuuKEzPZcVqm79kM2RdNr5fdObMb0a8j5UGUhlj2sf0LtxD/lwf1TtfRtG3U1BW9BJCBaoerFLYhY/nHmf9f3DdSBy5thentjCYsrkFLyPYe/G7kqpBSZ7XCjpPjKnGha62ocvDh6kAoaNZkl712cGB3aTEe8KxqwJ1+IiplPbEMyoQ95yVNrA9Wcbf+wj8lVkrtGLpCsQi3PQETmsMm3GCNuNKQ6dQ0Dh0JwpNwN6a1CerHRc=" May 06 11:01:35 volumio volumio[881]: info: Clearing queue after UPNP request May 06 11:01:35 volumio volumio[881]: info: CoreStateMachine::ClearQueue May 06 11:01:35 volumio volumio[881]: info: CoreStateMachine::stop May 06 11:01:35 volumio volumio[881]: info: CoreStateMachine::setConsumeUpdateService undefined May 06 11:01:35 volumio volumio[881]: info: CorePlayQueue::clearPlayQueue May 06 11:01:35 volumio volumio[881]: info: CorePlayQueue::saveQueue May 06 11:01:35 volumio volumio[881]: info: CoreCommandRouter::volumioPushState May 06 11:01:35 volumio volumio[881]: info: CoreCommandRouter::volumioPushQueue May 06 11:01:35 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:35 volumio volumio[881]: info: May 06 11:01:35 volumio volumio[881]: ---------------------------- MPD announces system playlist update May 06 11:01:35 volumio volumio[881]: info: Ignoring MPD Status Update May 06 11:01:35 volumio volumio[881]: error: updateQueue error: null May 06 11:01:35 volumio volumio[881]: info: ------------------------------ 1ms May 06 11:01:35 volumio volumio[881]: info: Starting UPNP Playback May 06 11:01:35 volumio volumio[881]: info: Preparing playback through UPNP May 06 11:01:35 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:01:35 volumio volumio[881]: info: CorePlayQueue::getTrack 0 May 06 11:01:35 volumio volumio[881]: info: CoreStateMachine::setConsumeUpdateService mpd May 06 11:01:36 volumio go-librespot[5379]: time="2024-05-06T11:01:36+09: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]" May 06 11:01:36 volumio go-librespot[5379]: time="2024-05-06T11:01:36+09:00" level=debug msg="completed keyexchange" May 06 11:01:36 volumio volumio[881]: info: Clearing queue after UPNP request May 06 11:01:36 volumio volumio[881]: info: CoreStateMachine::ClearQueue May 06 11:01:36 volumio volumio[881]: info: CoreStateMachine::stop May 06 11:01:36 volumio volumio[881]: info: CoreStateMachine::setConsumeUpdateService undefined May 06 11:01:36 volumio volumio[881]: info: CorePlayQueue::clearPlayQueue May 06 11:01:36 volumio volumio[881]: info: CorePlayQueue::saveQueue May 06 11:01:36 volumio volumio[881]: info: CoreCommandRouter::volumioPushState May 06 11:01:36 volumio volumio[881]: info: CoreCommandRouter::volumioPushQueue May 06 11:01:36 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:36 volumio volumio[881]: info: May 06 11:01:36 volumio volumio[881]: ---------------------------- MPD announces system playlist update May 06 11:01:36 volumio volumio[881]: info: Ignoring MPD Status Update May 06 11:01:36 volumio volumio[881]: error: updateQueue error: null May 06 11:01:36 volumio volumio[881]: info: ------------------------------ 1ms May 06 11:01:36 volumio volumio[881]: info: Starting UPNP Playback May 06 11:01:36 volumio volumio[881]: info: Preparing playback through UPNP May 06 11:01:36 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:01:36 volumio volumio[881]: info: CorePlayQueue::getTrack 0 May 06 11:01:36 volumio volumio[881]: info: CoreStateMachine::setConsumeUpdateService mpd May 06 11:01:36 volumio go-librespot[5379]: time="2024-05-06T11:01:36+09:00" level=debug msg="completed challenge" May 06 11:01:36 volumio go-librespot[5379]: time="2024-05-06T11:01:36+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:37 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:37 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:37 volumio volumio[881]: info: May 06 11:01:37 volumio volumio[881]: ---------------------------- MPD announces system playlist update May 06 11:01:37 volumio volumio[881]: info: Ignoring MPD Status Update May 06 11:01:37 volumio volumio[881]: info: ------------------------------ 1ms May 06 11:01:37 volumio volumio[881]: info: May 06 11:01:37 volumio volumio[881]: ---------------------------- MPD announces system playlist update May 06 11:01:37 volumio volumio[881]: info: Ignoring MPD Status Update May 06 11:01:37 volumio volumio[881]: info: ------------------------------ 1ms May 06 11:01:37 volumio volumio[881]: info: May 06 11:01:37 volumio volumio[881]: ---------------------------- MPD announces system playlist update May 06 11:01:37 volumio volumio[881]: info: Ignoring MPD Status Update May 06 11:01:37 volumio volumio[881]: info: May 06 11:01:37 volumio volumio[881]: ---------------------------- MPD announces system playlist update May 06 11:01:37 volumio volumio[881]: info: Ignoring MPD Status Update May 06 11:01:37 volumio volumio[881]: info: ------------------------------ 1ms May 06 11:01:37 volumio volumio[881]: info: ------------------------------ 1ms May 06 11:01:37 volumio volumio[881]: info: May 06 11:01:37 volumio volumio[881]: ---------------------------- MPD announces system playlist update May 06 11:01:37 volumio volumio[881]: info: Ignoring MPD Status Update May 06 11:01:37 volumio volumio[881]: info: ------------------------------ 0ms May 06 11:01:37 volumio volumio[881]: info: May 06 11:01:37 volumio volumio[881]: ---------------------------- MPD announces system playlist update May 06 11:01:37 volumio volumio[881]: info: Ignoring MPD Status Update May 06 11:01:37 volumio volumio[881]: info: ------------------------------ 1ms May 06 11:01:37 volumio volumio[881]: info: May 06 11:01:37 volumio volumio[881]: ---------------------------- MPD announces state update: player May 06 11:01:37 volumio volumio[881]: info: ControllerMpd::getState May 06 11:01:37 volumio volumio[881]: verbose: ControllerMpd::sendMpdCommand status May 06 11:01:37 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 May 06 11:01:37 volumio volumio[881]: info: May 06 11:01:37 volumio volumio[881]: ---------------------------- MPD announces system playlist update May 06 11:01:37 volumio volumio[881]: info: Ignoring MPD Status Update May 06 11:01:37 volumio volumio[881]: info: May 06 11:01:37 volumio volumio[881]: ---------------------------- MPD announces state update: player May 06 11:01:37 volumio volumio[881]: info: sendMpdCommand status took 249 milliseconds May 06 11:01:37 volumio volumio[881]: info: ControllerMpd::getState May 06 11:01:37 volumio volumio[881]: verbose: ControllerMpd::sendMpdCommand status May 06 11:01:37 volumio volumio[881]: verbose: ControllerMpd::parseState May 06 11:01:37 volumio volumio[881]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 06 11:01:37 volumio volumio[881]: info: ------------------------------ 3ms May 06 11:01:37 volumio volumio[881]: info: sendMpdCommand status took 1 milliseconds May 06 11:01:37 volumio volumio[881]: info: sendMpdCommand playlistinfo took 2 milliseconds May 06 11:01:37 volumio volumio[881]: verbose: ControllerMpd::parseState May 06 11:01:37 volumio volumio[881]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 06 11:01:37 volumio volumio[881]: verbose: ControllerMpd::parseTrackInfo May 06 11:01:37 volumio volumio[881]: info: ControllerMpd::pushState May 06 11:01:37 volumio volumio[881]: info: CoreCommandRouter::servicePushState May 06 11:01:37 volumio volumio[881]: verbose: In UPNP mode May 06 11:01:37 volumio volumio[881]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":282,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"06 화사 - LMM (4416 Flac)","artist":"华莎","album":"María","uri":"http://116.31.99.15/amobile.music.tc.qq.com/M500000lilHu2ZxdWC.mp3?guid=9599595CFC404289B2663212CFD7CA29&vkey=52CD3066F2BB615525DB8FE278209C7CCB3D340D44F6DDF3FDAFDAD71D9C6099451D05E15D05F50F91369098E60BFE6E0D9199DC158F157C&uin=1182014284&src=M500003BsZok1vZrch.mp3&redirect=1&fromtag=101042","trackType":""} May 06 11:01:37 volumio volumio[881]: verbose: CURRENT POSITION 0 May 06 11:01:37 volumio volumio[881]: info: CoreStateMachine::syncState stateService play May 06 11:01:37 volumio volumio[881]: info: CoreStateMachine::syncState currentStatus stop May 06 11:01:37 volumio volumio[881]: info: ------------------------------ 254ms May 06 11:01:37 volumio volumio[881]: info: sendMpdCommand playlistinfo took 2 milliseconds May 06 11:01:37 volumio volumio[881]: verbose: ControllerMpd::parseTrackInfo May 06 11:01:37 volumio volumio[881]: info: ControllerMpd::pushState May 06 11:01:37 volumio volumio[881]: info: CoreCommandRouter::servicePushState May 06 11:01:37 volumio volumio[881]: verbose: In UPNP mode May 06 11:01:37 volumio volumio[881]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":282,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"06 화사 - LMM (4416 Flac)","artist":"华莎","album":"María","uri":"http://116.31.99.15/amobile.music.tc.qq.com/M500000lilHu2ZxdWC.mp3?guid=9599595CFC404289B2663212CFD7CA29&vkey=52CD3066F2BB615525DB8FE278209C7CCB3D340D44F6DDF3FDAFDAD71D9C6099451D05E15D05F50F91369098E60BFE6E0D9199DC158F157C&uin=1182014284&src=M500003BsZok1vZrch.mp3&redirect=1&fromtag=101042","trackType":""} May 06 11:01:37 volumio volumio[881]: verbose: CURRENT POSITION 0 May 06 11:01:37 volumio volumio[881]: info: CoreStateMachine::syncState stateService play May 06 11:01:37 volumio volumio[881]: info: CoreStateMachine::syncState currentStatus play May 06 11:01:37 volumio volumio[881]: info: Received an update from plugin. extracting info from payload May 06 11:01:37 volumio volumio[881]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt May 06 11:01:37 volumio volumio[881]: info: CoreStateMachine::pushState May 06 11:01:37 volumio volumio[881]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 06 11:01:37 volumio volumio[881]: info: CoreCommandRouter::volumioPushState May 06 11:01:37 volumio volumio[881]: info: CoreStateMachine::pushState May 06 11:01:37 volumio volumio[881]: info: CoreCommandRouter::volumioPushState May 06 11:01:37 volumio volumio[881]: info: ------------------------------ 17ms May 06 11:01:37 volumio volumio[881]: info: CoreCommandRouter::volumioGetQueue May 06 11:01:37 volumio volumio[881]: info: CoreStateMachine::getQueue May 06 11:01:37 volumio volumio[881]: info: CorePlayQueue::getQueue May 06 11:01:37 volumio volumio[881]: info: CoreCommandRouter::volumioGetQueue May 06 11:01:37 volumio volumio[881]: info: CoreStateMachine::getQueue May 06 11:01:37 volumio volumio[881]: info: CorePlayQueue::getQueue May 06 11:01:37 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:37 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:40 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 220. May 06 11:01:40 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:40 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:40 volumio go-librespot[5402]: Librespot-go daemon starting... May 06 11:01:40 volumio go-librespot[5402]: time="2024-05-06T11:01:40+09:00" level=info msg="generated new device id: d9e02dbc41a66fa2cd4832511b5350a50e0c9423" May 06 11:01:40 volumio go-librespot[5402]: time="2024-05-06T11:01:40+09:00" level=debug msg="stored credentials not found" May 06 11:01:40 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:40 volumio go-librespot[5402]: time="2024-05-06T11:01:40+09:00" level=debug msg="new websocket client" May 06 11:01:40 volumio volumio[881]: info: Connection to go-librespot Websocket established May 06 11:01:41 volumio go-librespot[5402]: time="2024-05-06T11:01:41+09:00" level=debug msg="obtained new client token: AADLCHnt8mLCs7/+Wwc8l66iUmNg0tNHfEL0GtxfFtwbGMXv1j4O84yRLNWr9zs2YRwQSNBD+nFjUneg+AINsh2J3EZnDd5j17XB0wvcYuyNX+Mn+KS5Q4lodIbEzpQje9g1Q9DivUk5f+FjMY2RBYJNLAfekYCMwoMoFj+QHtuED0n6t8519iZVS/xv4o5q3uIEzrhZBCPqkgK1OomMTIXcb/nKqxE4/pY9fjRzV8pBLN/f5k1gbjfjuz21Fw==" May 06 11:01:41 volumio go-librespot[5402]: time="2024-05-06T11:01:41+09: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]" May 06 11:01:41 volumio go-librespot[5402]: time="2024-05-06T11:01:41+09:00" level=debug msg="completed keyexchange" May 06 11:01:42 volumio go-librespot[5402]: time="2024-05-06T11:01:42+09:00" level=debug msg="completed challenge" May 06 11:01:42 volumio go-librespot[5402]: time="2024-05-06T11:01:42+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:42 volumio volumio[881]: info: Connection to go-librespot Websocket closed May 06 11:01:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:43 volumio volumio[881]: info: Getting Spotify volume May 06 11:01:43 volumio volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:43 volumio volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 06 11:01:43 volumio volumio[881]: (node:881) 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: 123) May 06 11:01:43 volumio volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 May 06 11:01:43 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:01:43 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:45 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:45 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:45 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 221. May 06 11:01:45 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:45 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:45 volumio go-librespot[5452]: Librespot-go daemon starting... May 06 11:01:45 volumio go-librespot[5452]: time="2024-05-06T11:01:45+09:00" level=info msg="generated new device id: 42e168c7a14cfa72bb4a07d82c291ddf2e46d395" May 06 11:01:45 volumio go-librespot[5452]: time="2024-05-06T11:01:45+09:00" level=debug msg="stored credentials not found" May 06 11:01:46 volumio go-librespot[5452]: time="2024-05-06T11:01:46+09:00" level=debug msg="obtained new client token: AAD4jfeEdeJhGd8AiF7gsjMLkpxdMuTHTTUNKHaaFNR6B3ur8v3gfvlgr+AiMqopU2jBJJGvolfYQFMnpoX6CrUqD+XpgfqRXa1nhPwyAdFAiNfa44m3bvaCRuHZrJuPeXTt7tUd6eUjtfIFXCh6VLIjns5L4OPdnauIw52PRCKZU+khqdXZjzdSsZEYiA6cer5jM+Jv3Q5t+kKzFxrtW50demHW5v28FXBh+7u+HK93kPIBaoBsSURboUmjlg==" May 06 11:01:47 volumio go-librespot[5452]: time="2024-05-06T11:01:47+09: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]" May 06 11:01:47 volumio go-librespot[5452]: time="2024-05-06T11:01:47+09:00" level=debug msg="completed keyexchange" May 06 11:01:47 volumio go-librespot[5452]: time="2024-05-06T11:01:47+09:00" level=debug msg="completed challenge" May 06 11:01:47 volumio go-librespot[5452]: time="2024-05-06T11:01:47+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:48 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:48 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:48 volumio volumio[881]: info: peppy_screensaver: Start PeppyMeter May 06 11:01:50 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222. May 06 11:01:50 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:50 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:50 volumio go-librespot[5460]: Librespot-go daemon starting... May 06 11:01:50 volumio go-librespot[5460]: time="2024-05-06T11:01:50+09:00" level=info msg="generated new device id: 62f2b0724171e1d0c425d81210dea3559a5c96a8" May 06 11:01:50 volumio go-librespot[5460]: time="2024-05-06T11:01:50+09:00" level=debug msg="stored credentials not found" May 06 11:01:51 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:51 volumio go-librespot[5460]: time="2024-05-06T11:01:51+09:00" level=debug msg="new websocket client" May 06 11:01:51 volumio volumio[881]: info: Connection to go-librespot Websocket established May 06 11:01:51 volumio go-librespot[5460]: time="2024-05-06T11:01:51+09:00" level=debug msg="obtained new client token: AADvCmt23KEnvhHSlFxDXtOC4wrLpF5i6ArcgdQUQuAe6ukXpI5Q1A+K7JmDCLgT8TuomIDGzblmqo4Ew01BCEKq9XGyRLbdWBk93RV5paCNT7syMEJGZLFfE6vdl/nznfDK+uI1Tw219hjtqNJhmcAQxyLiHtS9ixVqnfqhc6lTCskxyBQE1Lqaf8wdD211fDR4LPL4/eSeqDxR9aYQUJKT+B99Kxxj7EId0GvUpLLpIsS4oBd0v0xmSO5KwA==" May 06 11:01:52 volumio go-librespot[5460]: time="2024-05-06T11:01:52+09: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]" May 06 11:01:52 volumio volumio[881]: error: [now-playing] API endpoint weather/fetchInfo returned error: Error: Could not access weather service: missing geographic coordinates. May 06 11:01:52 volumio volumio[881]: at WeatherAPI.fetchInfo (/data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:106:19) May 06 11:01:52 volumio volumio[881]: at Object.api (/data/plugins/user_interface/now_playing/dist/app/Handler.js:113:37) May 06 11:01:52 volumio volumio[881]: at /data/plugins/user_interface/now_playing/dist/app/Router.js:47:13 May 06 11:01:52 volumio volumio[881]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) May 06 11:01:52 volumio volumio[881]: at next (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/route.js:144:13) May 06 11:01:52 volumio volumio[881]: at Route.dispatch (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/route.js:114:3) May 06 11:01:52 volumio volumio[881]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) May 06 11:01:52 volumio volumio[881]: at /data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:284:15 May 06 11:01:52 volumio volumio[881]: at param (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:365:14) May 06 11:01:52 volumio volumio[881]: at param (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:376:14) May 06 11:01:52 volumio volumio[881]: at Function.process_params (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:421:3) May 06 11:01:52 volumio volumio[881]: at next (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:280:10) May 06 11:01:52 volumio volumio[881]: at Function.handle (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:175:3) May 06 11:01:52 volumio volumio[881]: at router (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:47:12) May 06 11:01:52 volumio volumio[881]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) May 06 11:01:52 volumio go-librespot[5460]: time="2024-05-06T11:01:52+09:00" level=debug msg="completed keyexchange" May 06 11:01:53 volumio go-librespot[5460]: time="2024-05-06T11:01:53+09:00" level=debug msg="completed challenge" May 06 11:01:53 volumio go-librespot[5460]: time="2024-05-06T11:01:53+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:53 volumio volumio[881]: info: Connection to go-librespot Websocket closed May 06 11:01:54 volumio volumio[881]: info: Getting Spotify volume May 06 11:01:54 volumio volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:54 volumio volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 06 11:01:54 volumio volumio[881]: (node:881) 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: 125) May 06 11:01:54 volumio volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 06 11:01:54 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:01:54 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:01:56 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:56 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:01:56 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:01:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 223. May 06 11:01:56 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:01:56 volumio systemd[1]: Started go-librespot Daemon. May 06 11:01:56 volumio go-librespot[5471]: Librespot-go daemon starting... May 06 11:01:56 volumio go-librespot[5471]: time="2024-05-06T11:01:56+09:00" level=info msg="generated new device id: 8ebbaa336f5501880d3a7e8735d323939d17d7bb" May 06 11:01:56 volumio go-librespot[5471]: time="2024-05-06T11:01:56+09:00" level=debug msg="stored credentials not found" May 06 11:01:57 volumio go-librespot[5471]: time="2024-05-06T11:01:57+09:00" level=debug msg="obtained new client token: AADsN1PIJMi6dT+XRYNp0xJhrM1xLg0FhI3Mzi4D/I5xvwFVpihbUFuJerwmG8vI4O7I75JLWZrYY6wTjj86XckPcQJWvZ+UDTgP/lu2dMyEp1Sb7cqVQjJn2qA3rhXYCRhu+/wpFNjCslQoyhYhSKIVQnx/oq2zuUK28KmyXWK5fnjcuuoLOH8YI8k1LHrnvD3w+Tsi0KvzRfZwBaod55l74pMZrpBzQvj5B8lOEUsLYxiAxq1HdC5XA8I=" May 06 11:01:57 volumio go-librespot[5471]: time="2024-05-06T11:01:57+09: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]" May 06 11:01:58 volumio go-librespot[5471]: time="2024-05-06T11:01:58+09:00" level=debug msg="completed keyexchange" May 06 11:01:58 volumio go-librespot[5471]: time="2024-05-06T11:01:58+09:00" level=debug msg="completed challenge" May 06 11:01:58 volumio go-librespot[5471]: time="2024-05-06T11:01:58+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:01:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:01:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:01:59 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:01:59 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:02:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:02:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 224. May 06 11:02:01 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:02:01 volumio systemd[1]: Started go-librespot Daemon. May 06 11:02:01 volumio go-librespot[5479]: Librespot-go daemon starting... May 06 11:02:01 volumio go-librespot[5479]: time="2024-05-06T11:02:01+09:00" level=info msg="generated new device id: 635be0b39a49d91c438238600b169ab0f03e172b" May 06 11:02:01 volumio go-librespot[5479]: time="2024-05-06T11:02:01+09:00" level=debug msg="stored credentials not found" May 06 11:02:02 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:02:02 volumio go-librespot[5479]: time="2024-05-06T11:02:02+09:00" level=debug msg="new websocket client" May 06 11:02:02 volumio volumio[881]: info: Connection to go-librespot Websocket established May 06 11:02:02 volumio go-librespot[5479]: time="2024-05-06T11:02:02+09:00" level=debug msg="obtained new client token: AACXxiCN2YvqYayP+Zq5A8i/Mi62v5Bc2O5Ut+8ed3tEmX1KXgA1dpgVlwEAs/GKBgfZ3MYNnjM8PmoYv/E5z7rlG2BMQpqfIBhKqzfQRQjTO8Nvx0gfMfbx4fTYj4pBPfgDhew7voKH/yvM1BLXFWJDaZ9V3Z4LGaf718VVF//WsX+z83TqwhI8lf/TecZJXsLJyf7QlsfL36L4OtSnNse49yF7Vujnkh3viI5s3oATFtaI8giozBBH/2aVbQ==" May 06 11:02:03 volumio volumio[881]: error: [now-playing] API endpoint metadata/fetchInfo returned error: Error: Token missing - Please provide a Genius Access Token in the Now Playing plugin settings. May 06 11:02:03 volumio volumio[881]: at MetadataAPI.fetchInfo (/data/plugins/user_interface/now_playing/dist/lib/api/MetadataAPI.js:75:19) May 06 11:02:03 volumio volumio[881]: at Object.api (/data/plugins/user_interface/now_playing/dist/app/Handler.js:113:37) May 06 11:02:03 volumio volumio[881]: at /data/plugins/user_interface/now_playing/dist/app/Router.js:47:13 May 06 11:02:03 volumio volumio[881]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) May 06 11:02:03 volumio volumio[881]: at next (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/route.js:144:13) May 06 11:02:03 volumio volumio[881]: at Route.dispatch (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/route.js:114:3) May 06 11:02:03 volumio volumio[881]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) May 06 11:02:03 volumio volumio[881]: at /data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:284:15 May 06 11:02:03 volumio volumio[881]: at param (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:365:14) May 06 11:02:03 volumio volumio[881]: at param (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:376:14) May 06 11:02:03 volumio volumio[881]: at Function.process_params (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:421:3) May 06 11:02:03 volumio volumio[881]: at next (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:280:10) May 06 11:02:03 volumio volumio[881]: at Function.handle (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:175:3) May 06 11:02:03 volumio volumio[881]: at router (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:47:12) May 06 11:02:03 volumio volumio[881]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) May 06 11:02:03 volumio go-librespot[5479]: time="2024-05-06T11:02:03+09: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]" May 06 11:02:04 volumio go-librespot[5479]: time="2024-05-06T11:02:04+09:00" level=debug msg="completed keyexchange" May 06 11:02:04 volumio go-librespot[5479]: time="2024-05-06T11:02:04+09:00" level=debug msg="completed challenge" May 06 11:02:04 volumio go-librespot[5479]: time="2024-05-06T11:02:04+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:02:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:02:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:02:04 volumio volumio[881]: info: Connection to go-librespot Websocket closed May 06 11:02:05 volumio volumio[881]: info: Getting Spotify volume May 06 11:02:05 volumio volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:02:05 volumio volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 06 11:02:05 volumio volumio[881]: (node:881) 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: 127) May 06 11:02:05 volumio volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 06 11:02:05 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:02:05 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:02:07 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:02:07 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:02:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:02:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 225. May 06 11:02:08 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:02:08 volumio systemd[1]: Started go-librespot Daemon. May 06 11:02:08 volumio go-librespot[5490]: Librespot-go daemon starting... May 06 11:02:08 volumio go-librespot[5490]: time="2024-05-06T11:02:08+09:00" level=info msg="generated new device id: 4ad0f07cc618e391993e8af1a269be44794cf402" May 06 11:02:08 volumio go-librespot[5490]: time="2024-05-06T11:02:08+09:00" level=debug msg="stored credentials not found" May 06 11:02:09 volumio go-librespot[5490]: time="2024-05-06T11:02:09+09:00" level=debug msg="obtained new client token: AABGMw7sJzfUw4HqCc5aIAIkI5fTzlwdpxb5ADu0eh0F2TFKZvb9iVwLMtERiJoNH1o27b/kQu4czqdwJ72UboVp7vgzKJWeboOrCbxNFfSl23qJm6KTq0aQCGqZG9A4LmzCItys1V+QSjUVR/XBkoxJ5XuEgHMlEfC3E7XWOhwkMHwUVeUUqauSUMRPCUUVxbv+ultg9PT7YDefOtpfftuxdBtOzZPnxwIYQb3EnLU15oPAUydBT5PHGvgVJg==" May 06 11:02:09 volumio go-librespot[5490]: time="2024-05-06T11:02:09+09: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]" May 06 11:02:09 volumio go-librespot[5490]: time="2024-05-06T11:02:09+09:00" level=debug msg="completed keyexchange" May 06 11:02:10 volumio volumio[881]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 May 06 11:02:10 volumio volumio[881]: info: touch_display: Setting screensaver timeout to 15 seconds. May 06 11:02:10 volumio go-librespot[5490]: time="2024-05-06T11:02:10+09:00" level=debug msg="completed challenge" May 06 11:02:10 volumio go-librespot[5490]: time="2024-05-06T11:02:10+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:02:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:02:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:02:10 volumio volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 9 May 06 11:02:10 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:02:10 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:02:10 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:02:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:02:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 226. May 06 11:02:13 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:02:13 volumio systemd[1]: Started go-librespot Daemon. May 06 11:02:13 volumio go-librespot[5528]: Librespot-go daemon starting... May 06 11:02:13 volumio go-librespot[5528]: time="2024-05-06T11:02:13+09:00" level=info msg="generated new device id: d3fc495071619e770c1d3207891574e9a8fdd4f5" May 06 11:02:13 volumio go-librespot[5528]: time="2024-05-06T11:02:13+09:00" level=debug msg="stored credentials not found" May 06 11:02:13 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:02:13 volumio go-librespot[5528]: time="2024-05-06T11:02:13+09:00" level=debug msg="new websocket client" May 06 11:02:13 volumio volumio[881]: info: Connection to go-librespot Websocket established May 06 11:02:14 volumio go-librespot[5528]: time="2024-05-06T11:02:14+09:00" level=debug msg="obtained new client token: AADpagsRYU/Y5xV3t2s9oFRdsg8vNEGpG9T6MLplAXeofz0ECcCh7aiyX9+s8yBTe5GC34g/piz1Tq8ekvIPeWGb2SKHRixX8waUE3/abBpezOpu5uEUG6os4wjROgdfcq86B5zXb5ADzz8vog7EOG7Dfob+KvT2tZhh7RkHqm5bjtvE3W46dhEPce/pNKd8P7Rp3qhIJNPSEOH9tITLlUn1bIZ3tL2Xt+xg/WX3ECOE5QKvOOBIOpUhW833aw==" May 06 11:02:15 volumio go-librespot[5528]: time="2024-05-06T11:02:15+09: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]" May 06 11:02:15 volumio go-librespot[5528]: time="2024-05-06T11:02:15+09:00" level=debug msg="completed keyexchange" May 06 11:02:16 volumio go-librespot[5528]: time="2024-05-06T11:02:16+09:00" level=debug msg="completed challenge" May 06 11:02:16 volumio go-librespot[5528]: time="2024-05-06T11:02:16+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:02:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:02:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:02:16 volumio volumio[881]: info: Connection to go-librespot Websocket closed May 06 11:02:16 volumio volumio[881]: info: Getting Spotify volume May 06 11:02:16 volumio volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:02:16 volumio volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 06 11:02:16 volumio volumio[881]: (node:881) 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: 128) May 06 11:02:16 volumio volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 May 06 11:02:16 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:02:16 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:02:19 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:02:19 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:02:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:02:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 227. May 06 11:02:19 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:02:19 volumio systemd[1]: Started go-librespot Daemon. May 06 11:02:19 volumio go-librespot[5537]: Librespot-go daemon starting... May 06 11:02:19 volumio go-librespot[5537]: time="2024-05-06T11:02:19+09:00" level=info msg="generated new device id: 9d98822d1d40dcbb3ecff7cd0434efe6b6a96297" May 06 11:02:19 volumio go-librespot[5537]: time="2024-05-06T11:02:19+09:00" level=debug msg="stored credentials not found" May 06 11:02:20 volumio go-librespot[5537]: time="2024-05-06T11:02:20+09:00" level=debug msg="obtained new client token: AACPh6OQa/OuaX1b27Zs6CNbVGhpx4U+lwxvaF0svZzG/+5laoDIYUzSnVMf3qQV53AOgPSt4H4hFkkrrYTLLjLCdCzzQXcVX+lJ52Dr0JRmYPHCLOz6xYcWDoTW8/ujWZanfl26S2ne5YVJ8ghDPEXbA4Egbe/sLc7v0ea9gft/kjgt5htciSlbBwQkMexes+oIPGmAhTHwd0+7obnk4P3UGMUJ+LBL+ZZmTnKuHv1Xn7dmwhyTc1vTGK8=" May 06 11:02:20 volumio volumio[881]: info: peppy_screensaver: Start PeppyMeter May 06 11:02:20 volumio go-librespot[5537]: time="2024-05-06T11:02:20+09: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]" May 06 11:02:21 volumio go-librespot[5537]: time="2024-05-06T11:02:21+09:00" level=debug msg="completed keyexchange" May 06 11:02:21 volumio go-librespot[5537]: time="2024-05-06T11:02:21+09:00" level=debug msg="completed challenge" May 06 11:02:21 volumio go-librespot[5537]: time="2024-05-06T11:02:21+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:02:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:02:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:02:22 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:02:22 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:02:24 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:02:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 228. May 06 11:02:24 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:02:24 volumio systemd[1]: Started go-librespot Daemon. May 06 11:02:24 volumio go-librespot[5545]: Librespot-go daemon starting... May 06 11:02:24 volumio go-librespot[5545]: time="2024-05-06T11:02:24+09:00" level=info msg="generated new device id: 284cbb16b6c1293248535ec50d39e74690c33517" May 06 11:02:24 volumio go-librespot[5545]: time="2024-05-06T11:02:24+09:00" level=debug msg="stored credentials not found" May 06 11:02:25 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:02:25 volumio go-librespot[5545]: time="2024-05-06T11:02:25+09:00" level=debug msg="new websocket client" May 06 11:02:25 volumio volumio[881]: info: Connection to go-librespot Websocket established May 06 11:02:25 volumio go-librespot[5545]: time="2024-05-06T11:02:25+09:00" level=debug msg="obtained new client token: AADod4UVzrT/CqcvCodanggatFC2KHjuXAgOrJJIAsCg2tSwy309rNUFiErpnLFXorkmhX+fZ1SErM2xPjl48K7p+5zIOG+chp1oilyWAnIpifSFEaxyyO/DDfCd3D8Rw/tpxihIMgdvdbL3oHpRj5Ja4ATEl/hnby8a2Y4pBKoE4j7Cjqn1jKNrJ6Sq0GtNUcPdhawytGMl7L+aFWa/ZxZoZjjUKNDGiZMr/eIJ+nK6dBsVS3iuI8LFCIdzOg==" May 06 11:02:26 volumio go-librespot[5545]: time="2024-05-06T11:02:26+09: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]" May 06 11:02:26 volumio go-librespot[5545]: time="2024-05-06T11:02:26+09:00" level=debug msg="completed keyexchange" May 06 11:02:27 volumio go-librespot[5545]: time="2024-05-06T11:02:27+09:00" level=debug msg="completed challenge" May 06 11:02:27 volumio go-librespot[5545]: time="2024-05-06T11:02:27+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:02:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:02:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:02:27 volumio volumio[881]: info: Connection to go-librespot Websocket closed May 06 11:02:28 volumio volumio[881]: info: Getting Spotify volume May 06 11:02:28 volumio volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:02:28 volumio volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 06 11:02:28 volumio volumio[881]: (node:881) 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: 129) May 06 11:02:28 volumio volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 06 11:02:28 volumio volumio[881]: info: CoreCommandRouter::volumioGetState May 06 11:02:28 volumio volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 May 06 11:02:30 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:02:30 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:02:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:02:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 229. May 06 11:02:30 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:02:30 volumio systemd[1]: Started go-librespot Daemon. May 06 11:02:30 volumio go-librespot[5556]: Librespot-go daemon starting... May 06 11:02:30 volumio go-librespot[5556]: time="2024-05-06T11:02:30+09:00" level=info msg="generated new device id: 437f77eeecc3de57fe4ab7502b41d590293159fe" May 06 11:02:30 volumio go-librespot[5556]: time="2024-05-06T11:02:30+09:00" level=debug msg="stored credentials not found" May 06 11:02:31 volumio go-librespot[5556]: time="2024-05-06T11:02:31+09:00" level=debug msg="obtained new client token: AAB5NBiKDKJQFB7RcWIEaL3uxc9qOUIp33YkyxynOYogl2F89Ez06nga4Coo3wtVf03zeGokocy6blkmPoafKSedWaYWq8d3VcMpLDVnvUXNoOrBfG5D6ph2bPQYOtaq/Cq0Uy4jbsthukEznGKp8yqcSLQVfZeY7p7riQPHDS2p7D7jeUOwVt86XFgdKGyPo8leffuYvE95gVGjELtyTKRWE7WVISN2XHF0VWtBLjP9S1TPlKNOc0FZRzI=" May 06 11:02:31 volumio go-librespot[5556]: time="2024-05-06T11:02:31+09: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]" May 06 11:02:31 volumio go-librespot[5556]: time="2024-05-06T11:02:31+09:00" level=debug msg="completed keyexchange" May 06 11:02:32 volumio go-librespot[5556]: time="2024-05-06T11:02:32+09:00" level=debug msg="completed challenge" May 06 11:02:32 volumio go-librespot[5556]: time="2024-05-06T11:02:32+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 06 11:02:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 06 11:02:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 06 11:02:33 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:02:33 volumio volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 06 11:02:35 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 06 11:02:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 230. May 06 11:02:35 volumio systemd[1]: Stopped go-librespot Daemon. May 06 11:02:35 volumio systemd[1]: Started go-librespot Daemon. May 06 11:02:35 volumio go-librespot[5564]: Librespot-go daemon starting... May 06 11:02:35 volumio go-librespot[5564]: time="2024-05-06T11:02:35+09:00" level=info msg="generated new device id: d21e6f9f3585c142dd5f7731cc680a0d9cbf79da" May 06 11:02:35 volumio go-librespot[5564]: time="2024-05-06T11:02:35+09:00" level=debug msg="stored credentials not found" May 06 11:02:36 volumio volumio[881]: info: Initializing connection to go-librespot Websocket May 06 11:02:36 volumio go-librespot[5564]: time="2024-05-06T11:02:36+09:00" level=debug msg="new websocket client" May 06 11:02:36 volumio volumio[881]: info: Connection to go-librespot Websocket established May 06 11:02:36 volumio volumio[881]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 06 11:02:36 volumio volumio[881]: Error: connect ETIMEDOUT 204.79.197.217:443 May 06 11:02:36 volumio volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { May 06 11:02:36 volumio volumio[881]: errno: -110, May 06 11:02:36 volumio volumio[881]: code: 'ETIMEDOUT', May 06 11:02:36 volumio volumio[881]: syscall: 'connect', May 06 11:02:36 volumio volumio[881]: address: '204.79.197.217', May 06 11:02:36 volumio volumio[881]: port: 443 May 06 11:02:36 volumio volumio[881]: } May 06 11:02:36 volumio volumio[881]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 06 11:02:36 volumio go-librespot[5564]: time="2024-05-06T11:02:36+09:00" level=debug msg="obtained new client token: AABDGGvqcZSxdZkcr6L0jlTFkMnggAtNGZ+F8O69TstBOJlDUxejbYg5g9ILBCAHNOv1bPtGChsKsaoaLSCKIBGHrtYqKLJBgVKoFcYCS+rk7EAAbzXY22PZKINsdSz1B3sus9M5blXPgF5/S9YORN5uP9238mR4+aGcoHJk/kU2KkckAOPpDlkhl9Y5pPFRZGIk74xLVhLBCNaKoPI/6OYjb6fyxGGj1fenP081eF8uFj9a9CnS3UxelYTflQ==" May 06 11:02:36 volumio sudo[5581]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-06 11:01 May 06 11:02:36 volumio sudo[5581]: 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"