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