-- Logs begin at Thu 2019-02-14 11:12:01 CET, end at Thu 2024-05-02 11:49:33 CEST. -- May 02 11:48:00 volumio wpa_supplicant[825]: RRM: Ignoring radio measurement request: Not RRM network May 02 11:48:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 55. May 02 11:48:00 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:01 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:01 volumio go-librespot[2412]: Librespot-go daemon starting... May 02 11:48:01 volumio go-librespot[2412]: time="2024-05-02T11:48:01+02:00" level=info msg="generated new device id: 2df1746aa5e3bf2f9acd164df0436f03390b3a15" May 02 11:48:01 volumio go-librespot[2412]: time="2024-05-02T11:48:01+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:01 volumio go-librespot[2412]: time="2024-05-02T11:48:01+02:00" level=debug msg="obtained new client token: AADMobBAtrFn56bqlSivslVQjSnklhJXTvWEBqdFJNinyFlGARFZlhQbVFKAnbn6iOKFcFs7fqK+esjlnFkEkBbSgCtjU62Tez58BsBSzWT3ERWnx+umPqAXDYYAIuSedaUS252er4aHEeChlnUmZK4TcJU4gDpIFigN2ZEt3DAQafbnPstyfLu5xUmPhyLZf2Qc8fDN4fnj3fKwiZenl24TwnRzTYXEMkKRa3BkH6zl3zkkg+M/1AzZyKwE" May 02 11:48:01 volumio go-librespot[2412]: time="2024-05-02T11:48:01+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:48:01 volumio go-librespot[2412]: time="2024-05-02T11:48:01+02:00" level=debug msg="completed keyexchange" May 02 11:48:02 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:02 volumio go-librespot[2412]: time="2024-05-02T11:48:02+02:00" level=debug msg="new websocket client" May 02 11:48:02 volumio volumio[909]: info: Connection to go-librespot Websocket established May 02 11:48:02 volumio go-librespot[2412]: time="2024-05-02T11:48:02+02:00" level=debug msg="completed challenge" May 02 11:48:02 volumio go-librespot[2412]: time="2024-05-02T11:48:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:02 volumio volumio[909]: info: Connection to go-librespot Websocket closed May 02 11:48:04 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:48:04 volumio volumio[909]: info: Preload queue cleared May 02 11:48:05 volumio volumio[909]: info: Getting Spotify volume May 02 11:48:05 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:05 volumio volumio[909]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 02 11:48:05 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 21) May 02 11:48:05 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 02 11:48:05 volumio volumio[909]: info: CoreCommandRouter::volumioGetState May 02 11:48:05 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:48:05 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 May 02 11:48:05 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:05 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:05 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56. May 02 11:48:05 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:05 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:05 volumio go-librespot[2421]: Librespot-go daemon starting... May 02 11:48:05 volumio go-librespot[2421]: time="2024-05-02T11:48:05+02:00" level=info msg="generated new device id: 66123d7748fb00d9ed97d88eabc3646afc97598a" May 02 11:48:05 volumio go-librespot[2421]: time="2024-05-02T11:48:05+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:05 volumio go-librespot[2421]: time="2024-05-02T11:48:05+02:00" level=debug msg="obtained new client token: AABOg9gGzCB3BPPhZ0gGx0q+aRtas8RhS+FUuAwVteceoDYQrMYXqtHojBx0tzo/8InLDItaCev5rZdPibQZ7OOS+Q7pYTFGrx3w8RCiG1ij6ZpUSXmKZOi6FEkwCsF1qNHCwIMZjcSPLvTLTaSWvnjQW3XgnYGEKk2wsPP5XHzJ/ruD7OsLGgCpaRk2HHJTqWFGluU+hYqED1Q/RwcZyLdset7dtqL0BYdPrgh+TFo5wUBvNr/fJvLCrKXI" May 02 11:48:06 volumio go-librespot[2421]: time="2024-05-02T11:48:06+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:48:06 volumio go-librespot[2421]: time="2024-05-02T11:48:06+02:00" level=debug msg="completed keyexchange" May 02 11:48:07 volumio go-librespot[2421]: time="2024-05-02T11:48:07+02:00" level=debug msg="completed challenge" May 02 11:48:07 volumio wpa_supplicant[825]: RRM: Ignoring radio measurement request: Not RRM network May 02 11:48:07 volumio go-librespot[2421]: time="2024-05-02T11:48:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:08 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:08 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57. May 02 11:48:10 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:10 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:10 volumio go-librespot[2429]: Librespot-go daemon starting... May 02 11:48:10 volumio go-librespot[2429]: time="2024-05-02T11:48:10+02:00" level=info msg="generated new device id: f169fe0f218d227f7a486e75b25119c56c1ecf00" May 02 11:48:10 volumio go-librespot[2429]: time="2024-05-02T11:48:10+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:10 volumio go-librespot[2429]: time="2024-05-02T11:48:10+02:00" level=debug msg="obtained new client token: AACDIrBpIp6S3V76KHJftC+sTApiGLOpwhQtthS2OWvRoRr2HxQTVz4DxZCfmNft3qaKAwaUKZPcuGUIbj/jwHvj25TQk0i1DtP4cuMwIKh0fZNdjckOfFd9jI7B28bVUvb5xt6otXTJfVF/EDdxEu71iFBXH30tYBsn5ObTXTeoLNeapAUl5/85409LTSj+LePHXRSm3pzkyQec9e/cxp85V2gTWKoFwGtcRHPoFWyXl+da9bYWR2aaeIkV" May 02 11:48:11 volumio go-librespot[2429]: time="2024-05-02T11:48:11+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:48:11 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:11 volumio go-librespot[2429]: time="2024-05-02T11:48:11+02:00" level=debug msg="new websocket client" May 02 11:48:11 volumio volumio[909]: info: Connection to go-librespot Websocket established May 02 11:48:11 volumio go-librespot[2429]: time="2024-05-02T11:48:11+02:00" level=debug msg="completed keyexchange" May 02 11:48:11 volumio go-librespot[2429]: time="2024-05-02T11:48:11+02:00" level=debug msg="completed challenge" May 02 11:48:11 volumio go-librespot[2429]: time="2024-05-02T11:48:11+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:11 volumio volumio[909]: info: Connection to go-librespot Websocket closed May 02 11:48:13 volumio wpa_supplicant[825]: RRM: Ignoring radio measurement request: Not RRM network May 02 11:48:14 volumio volumio[909]: info: Getting Spotify volume May 02 11:48:14 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:14 volumio volumio[909]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 02 11:48:14 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 22) May 02 11:48:14 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 02 11:48:14 volumio volumio[909]: info: CoreCommandRouter::volumioGetState May 02 11:48:14 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:48:14 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 May 02 11:48:14 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:14 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 58. May 02 11:48:14 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:15 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:15 volumio go-librespot[2437]: Librespot-go daemon starting... May 02 11:48:15 volumio go-librespot[2437]: time="2024-05-02T11:48:15+02:00" level=info msg="generated new device id: e643cf37ce111c7753c6a50724a2b30a78262fa5" May 02 11:48:15 volumio go-librespot[2437]: time="2024-05-02T11:48:15+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:15 volumio go-librespot[2437]: time="2024-05-02T11:48:15+02:00" level=debug msg="obtained new client token: AACpLbdptb1ck3eU7UW6tEojdQDqOg8i1yeGTZ97TyGUdOVJ9kFghxzmbiKvZN32h8dfXSkusrQtdVDMex9Z4+1pFRCu2muhWwEgOYpvZ1129K7YgYHvV/+uqog/DYDGni57y/nGPZ1KWyiRQv9P+Q1NVW3VWRNHvWJ9d2TQFAALNqonc0zRm4hqK/HzBWlFXN8Fx1LrFDQmPE4egSPnquEspMJ9FKPrsmx5lszpQ7pn1d91IotKU6NXRH1S" May 02 11:48:15 volumio go-librespot[2437]: time="2024-05-02T11:48:15+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:48:15 volumio go-librespot[2437]: time="2024-05-02T11:48:15+02:00" level=debug msg="completed keyexchange" May 02 11:48:16 volumio go-librespot[2437]: time="2024-05-02T11:48:16+02:00" level=debug msg="completed challenge" May 02 11:48:16 volumio go-librespot[2437]: time="2024-05-02T11:48:16+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:17 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:17 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 59. May 02 11:48:19 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:19 volumio wpa_supplicant[825]: RRM: Ignoring radio measurement request: Not RRM network May 02 11:48:19 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:19 volumio go-librespot[2445]: Librespot-go daemon starting... May 02 11:48:19 volumio go-librespot[2445]: time="2024-05-02T11:48:19+02:00" level=info msg="generated new device id: 83f1b3d0f5f554ba94bbd537e190789d5fc9ba6a" May 02 11:48:19 volumio go-librespot[2445]: time="2024-05-02T11:48:19+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:19 volumio go-librespot[2445]: time="2024-05-02T11:48:19+02:00" level=debug msg="obtained new client token: AAClx3ldkNcTt0I6phas/tNbCIpn8MSDQeQtfj6sO9h/dJtpWO2bdWHXZcl/KjYx5vTuSLBN7Ci1TqVAYfanbKEQdr1SZsbhPqhEMgzJ8iipWY2pk8w1kipOBYMV2DUTim79Ih3VcaYE1eFEKmKyOE5IRup+DB+DibRR/vgTM646TOtmaOrBi3xTiri9a45fLK/rrzJudFWx1CgBxqTFvr48MOFQfvKtDNrQNd/Jnk8PJBIdaEC9XvGveOIF" May 02 11:48:20 volumio go-librespot[2445]: time="2024-05-02T11:48:20+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 02 11:48:20 volumio go-librespot[2445]: time="2024-05-02T11:48:20+02:00" level=debug msg="completed keyexchange" May 02 11:48:20 volumio go-librespot[2445]: time="2024-05-02T11:48:20+02:00" level=debug msg="completed challenge" May 02 11:48:20 volumio go-librespot[2445]: time="2024-05-02T11:48:20+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:20 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:20 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 60. May 02 11:48:23 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:23 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:23 volumio go-librespot[2454]: Librespot-go daemon starting... May 02 11:48:23 volumio go-librespot[2454]: time="2024-05-02T11:48:23+02:00" level=info msg="generated new device id: d5dd73676a54d8612cd250edbd009c9cbb8e822a" May 02 11:48:23 volumio go-librespot[2454]: time="2024-05-02T11:48:23+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:23 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:23 volumio go-librespot[2454]: time="2024-05-02T11:48:23+02:00" level=debug msg="new websocket client" May 02 11:48:23 volumio volumio[909]: info: Connection to go-librespot Websocket established May 02 11:48:24 volumio go-librespot[2454]: time="2024-05-02T11:48:24+02:00" level=debug msg="obtained new client token: AAAaRYhUIjIICTNEWNzio3Ur/HUphKi8RSKMA+U6zxv4PcP+ATXXKILOf+0/z+95DykR95xZjaJoqT3aLC/6Qf7CpnEqzmVGSg2FdlmLhtw3CW9BE82auax6lVjrvEJFaYBkS/HRJYXiX0dQXzP7UbhwQlGORBbreejsNGQU203RBs/z6j+0erRjwyZvXJONZsj0Uz+C5/+ddt268SHE7D3BlrFMWxNk8/hOYBqbdaffg21D3dHXeWZbUQ==" May 02 11:48:24 volumio go-librespot[2454]: time="2024-05-02T11:48:24+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:48:24 volumio go-librespot[2454]: time="2024-05-02T11:48:24+02:00" level=debug msg="completed keyexchange" May 02 11:48:24 volumio go-librespot[2454]: time="2024-05-02T11:48:24+02:00" level=debug msg="completed challenge" May 02 11:48:24 volumio go-librespot[2454]: time="2024-05-02T11:48:24+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:24 volumio volumio[909]: info: Connection to go-librespot Websocket closed May 02 11:48:26 volumio wpa_supplicant[825]: RRM: Ignoring radio measurement request: Not RRM network May 02 11:48:26 volumio volumio[909]: info: Getting Spotify volume May 02 11:48:26 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:26 volumio volumio[909]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 02 11:48:26 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 23) May 02 11:48:27 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 02 11:48:27 volumio volumio[909]: info: CoreCommandRouter::volumioGetState May 02 11:48:27 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:48:27 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 May 02 11:48:27 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:27 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 61. May 02 11:48:27 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:28 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:28 volumio go-librespot[2462]: Librespot-go daemon starting... May 02 11:48:28 volumio go-librespot[2462]: time="2024-05-02T11:48:28+02:00" level=info msg="generated new device id: 9ee43be89c7cfd6c825fe673fcd6515dcc25bae5" May 02 11:48:28 volumio go-librespot[2462]: time="2024-05-02T11:48:28+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:28 volumio go-librespot[2462]: time="2024-05-02T11:48:28+02:00" level=debug msg="obtained new client token: AAB8xpuZyOFuAMWszSKo3f8G9w2h96p7JhSQg5O3Mii/xZcbNa9wCklcwAR1gg8ouwoxVrlmJQyTVcrSw4voGtjs6BRQPYQKygOxMZ1bJ9U5yBTpjiPGWpBgX0AXcaxTU0PxGrd3jxMRP+i7EaO2cwI2gEx4DWYEJVQb+nXfUuyq+4axGuBviXWjBl932k7IDvD9KyXcm9TwMGhmt6oD1r9Hh8ha+WzAXfpQe9NAmRhTpt/Gk6NF4+B9EFJj" May 02 11:48:28 volumio go-librespot[2462]: time="2024-05-02T11:48:28+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 02 11:48:28 volumio go-librespot[2462]: time="2024-05-02T11:48:28+02:00" level=debug msg="completed keyexchange" May 02 11:48:29 volumio go-librespot[2462]: time="2024-05-02T11:48:29+02:00" level=debug msg="completed challenge" May 02 11:48:29 volumio go-librespot[2462]: time="2024-05-02T11:48:29+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:30 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:30 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 62. May 02 11:48:32 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:32 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:32 volumio go-librespot[2470]: Librespot-go daemon starting... May 02 11:48:32 volumio go-librespot[2470]: time="2024-05-02T11:48:32+02:00" level=info msg="generated new device id: 1f4ba6b65a35ad172b298e5b354d528e03ac9ecb" May 02 11:48:32 volumio go-librespot[2470]: time="2024-05-02T11:48:32+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:32 volumio go-librespot[2470]: time="2024-05-02T11:48:32+02:00" level=debug msg="obtained new client token: AADQaGH5DYYOk2If+CecZobS+0aC7rcc3Z2bDHSA0qrp9BmkBjnZXNadR6/9NKyDyGvmnxLa2dFK022LMX/LvS91EdaWTCUErPu7kwT2/sc/CkrT6gPtsDiXHeeYYAL6HhizBJo0PSv5lYlw6ZdVKC+iwriV2roCde1mu72bFHbaMMW/je3YYbmQcgRnl3V8p2qRykr/y+E+KG24VtoUGOVVb/Gegbh2LAFAGEpFkNyu6GugWiP7tx8uMtaX" May 02 11:48:33 volumio go-librespot[2470]: time="2024-05-02T11:48:33+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 02 11:48:33 volumio wpa_supplicant[825]: RRM: Ignoring radio measurement request: Not RRM network May 02 11:48:33 volumio go-librespot[2470]: time="2024-05-02T11:48:33+02:00" level=debug msg="completed keyexchange" May 02 11:48:33 volumio go-librespot[2470]: time="2024-05-02T11:48:33+02:00" level=debug msg="completed challenge" May 02 11:48:33 volumio go-librespot[2470]: time="2024-05-02T11:48:33+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:33 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:33 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:36 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:36 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 63. May 02 11:48:36 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:37 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:37 volumio go-librespot[2478]: Librespot-go daemon starting... May 02 11:48:37 volumio go-librespot[2478]: time="2024-05-02T11:48:37+02:00" level=info msg="generated new device id: 7374c159dbe37cd1c8fffce312929cd0456a3db6" May 02 11:48:37 volumio go-librespot[2478]: time="2024-05-02T11:48:37+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:37 volumio go-librespot[2478]: time="2024-05-02T11:48:37+02:00" level=debug msg="obtained new client token: AACWHpDdOegLBy4cVsdHOoCQbVgg/s67JQ7Ve/drRg79MMoKs6bnnrgP7gKsSy7I5Z13RJnnP7Z5W97TMH4LmdB8vU+1UOaOXGl7L689+OuHohHXiII/CCK/XBA1FV9KKpYQEJv4ijxLFOYMZQUXi4YEAdq0w+AJx1DuvaWms8hsbR9YTSl3cvyH3IGTgOf0zyvqbM0BBG3JJU5aQ41KFUH3dyFYrpOE+1CeqwVId68IdQhhS2sid0oxxpWQ" May 02 11:48:37 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:48:37 volumio volumio[909]: info: Preload queue cleared May 02 11:48:37 volumio go-librespot[2478]: time="2024-05-02T11:48:37+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 02 11:48:37 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:48:37 volumio volumio[909]: info: Preload queue cleared May 02 11:48:37 volumio go-librespot[2478]: time="2024-05-02T11:48:37+02:00" level=debug msg="completed keyexchange" May 02 11:48:38 volumio go-librespot[2478]: time="2024-05-02T11:48:38+02:00" level=debug msg="completed challenge" May 02 11:48:38 volumio go-librespot[2478]: time="2024-05-02T11:48:38+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:38 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:48:39 volumio wpa_supplicant[825]: RRM: Ignoring radio measurement request: Not RRM network May 02 11:48:39 volumio volumio[909]: info: Preload queue cleared May 02 11:48:39 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:39 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:40 volumio volumio[909]: info: Preload queue cleared May 02 11:48:40 volumio volumio[909]: info: CoreCommandRouter::volumioReplaceandPlayItems May 02 11:48:40 volumio volumio[909]: info: CoreStateMachine::ClearQueue May 02 11:48:40 volumio volumio[909]: info: CoreStateMachine::stop May 02 11:48:40 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:48:40 volumio volumio[909]: info: CorePlayQueue::clearPlayQueue May 02 11:48:40 volumio volumio[909]: info: CorePlayQueue::saveQueue May 02 11:48:40 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue May 02 11:48:40 volumio volumio[909]: info: CoreStateMachine::addQueueItems May 02 11:48:40 volumio volumio[909]: info: CorePlayQueue::addQueueItems May 02 11:48:40 volumio volumio[909]: info: Preload queue cleared May 02 11:48:40 volumio volumio[909]: info: Adding Item to queue: upnp/folder/http://192.168.1.106:32469/ContentDirectory/737094ed-b28a-674c-d6a5-57e2f76bbd3d/control.xml@5a2ee305b189e320212f May 02 11:48:40 volumio volumio[909]: info: Exploding uri upnp/folder/http://192.168.1.106:32469/ContentDirectory/737094ed-b28a-674c-d6a5-57e2f76bbd3d/control.xml@5a2ee305b189e320212f in service upnp_browser May 02 11:48:41 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue May 02 11:48:41 volumio volumio[909]: info: CorePlayQueue::saveQueue May 02 11:48:41 volumio volumio[909]: info: CoreStateMachine::updateTrackBlock May 02 11:48:41 volumio volumio[909]: info: CorePlayQueue::getTrackBlock May 02 11:48:41 volumio volumio[909]: info: CoreCommandRouter::volumioPlay May 02 11:48:41 volumio volumio[909]: info: CoreStateMachine::play index 0 May 02 11:48:41 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:48:41 volumio volumio[909]: info: CoreStateMachine::stop May 02 11:48:41 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:48:41 volumio volumio[909]: info: CoreStateMachine::play index undefined May 02 11:48:41 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:48:41 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:48:41 volumio volumio[909]: info: CoreStateMachine::startPlaybackTimer May 02 11:48:41 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:48:41 volumio volumio[909]: info: [1714643321045] ControllerUPNPBrowser::clearAddPlayTrack May 02 11:48:41 volumio volumio[909]: verbose: ControllerMpd::sendMpdCommand stop May 02 11:48:41 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 64. May 02 11:48:41 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:41 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:41 volumio go-librespot[2527]: Librespot-go daemon starting... May 02 11:48:41 volumio go-librespot[2527]: time="2024-05-02T11:48:41+02:00" level=info msg="generated new device id: 4f602c28632ce615591ccd5e2cc752f2740ca199" May 02 11:48:41 volumio go-librespot[2527]: time="2024-05-02T11:48:41+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:41 volumio go-librespot[2527]: time="2024-05-02T11:48:41+02:00" level=debug msg="obtained new client token: AAAWo8Pw+2VXVFFSPh4YIiekhF03sJM+Xeyp7h4y76gBrgrPWVvQsVP5n/G34p0PCpUJc9Xl5/4LgGqM6nD4O3urVQblc9dJhaggQo3xMYIfRu6N9AUVjwL5vst+fa8H5BpqwZlKN9cuUF+vEmYk0AtDQEVtoPPZJr6RsXfjSl1DaiPE2WhBNvkzGw6hQEO1gc5ga7qgcwZVRbk4d4g6eV4Patf6+062B9zcoG9spBHuXByT1UxwRbwFPeqc" May 02 11:48:41 volumio go-librespot[2527]: time="2024-05-02T11:48:41+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 02 11:48:41 volumio go-librespot[2527]: time="2024-05-02T11:48:41+02:00" level=debug msg="completed keyexchange" May 02 11:48:42 volumio go-librespot[2527]: time="2024-05-02T11:48:42+02:00" level=debug msg="completed challenge" May 02 11:48:42 volumio go-librespot[2527]: time="2024-05-02T11:48:42+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:42 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:42 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:45 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 65. May 02 11:48:45 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:45 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:45 volumio go-librespot[2535]: Librespot-go daemon starting... May 02 11:48:45 volumio go-librespot[2535]: time="2024-05-02T11:48:45+02:00" level=info msg="generated new device id: 95c1063f3d425a91caf7b31a3bcb47f78bb94f44" May 02 11:48:45 volumio go-librespot[2535]: time="2024-05-02T11:48:45+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:45 volumio go-librespot[2535]: time="2024-05-02T11:48:45+02:00" level=debug msg="obtained new client token: AADzTRH6WYSiOXgXQlsr9wMkdZDsAMBrQnHoNITYsXKtjvddgtrkxGOaXnWTsX2APSDTJyYHw8Fo8z9DXHZe7EfwtZijAD+b42CRw1mqnkCauPWcY/p535NCwocmNNcU8Sj5BuyrhjXHgJ4AuCJlFYwNjmJPANJpZznK9X51HKZq8OjGi6pJrXEwuDeJU5elZ3qno6PU94n33lm5ed4RDPTt/ZfUvENI0aQAbJ7GAUgCFX96hNfcLzYGOWyF" May 02 11:48:45 volumio wpa_supplicant[825]: RRM: Ignoring radio measurement request: Not RRM network May 02 11:48:45 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:46 volumio go-librespot[2535]: time="2024-05-02T11:48:46+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 02 11:48:46 volumio go-librespot[2535]: time="2024-05-02T11:48:46+02:00" level=debug msg="completed keyexchange" May 02 11:48:46 volumio go-librespot[2535]: time="2024-05-02T11:48:46+02:00" level=debug msg="completed challenge" May 02 11:48:46 volumio go-librespot[2535]: time="2024-05-02T11:48:46+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:49 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 66. May 02 11:48:49 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:49 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:49 volumio go-librespot[2544]: Librespot-go daemon starting... May 02 11:48:49 volumio go-librespot[2544]: time="2024-05-02T11:48:49+02:00" level=info msg="generated new device id: e3b881a0ebcab96e70a21ee732a7f45f7676f7ef" May 02 11:48:49 volumio go-librespot[2544]: time="2024-05-02T11:48:49+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:50 volumio go-librespot[2544]: time="2024-05-02T11:48:50+02:00" level=debug msg="obtained new client token: AAAruDgytW+uZUOA/sRbIGD4QwPvKPd8dUvS7og2Y0cp+iWsqJk9Ju4V6uxK+GhpZ0dKFz6ORufrWkaoH4b4tvX7RAU8D9esbVBCsNX/Vs2vL3+CxxU6faSqwJDSpDf4pkdu1VKs8NEn2cSLJYzkv6uZCQoiwpslZWjwZZgBugNz74MZqMx/0wHDnTZ+rHywzsmnaPKpktktqiRrp6oDhjEPxcIBMY8rEFacqVJgNSUv0K1WxJhJjWdfQg==" May 02 11:48:50 volumio go-librespot[2544]: time="2024-05-02T11:48:50+02:00" level=debug msg="new websocket client" May 02 11:48:50 volumio volumio[909]: info: Connection to go-librespot Websocket established May 02 11:48:50 volumio go-librespot[2544]: time="2024-05-02T11:48:50+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:48:50 volumio go-librespot[2544]: time="2024-05-02T11:48:50+02:00" level=debug msg="completed keyexchange" May 02 11:48:51 volumio go-librespot[2544]: time="2024-05-02T11:48:51+02:00" level=debug msg="completed challenge" May 02 11:48:51 volumio go-librespot[2544]: time="2024-05-02T11:48:51+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:51 volumio volumio[909]: info: Connection to go-librespot Websocket closed May 02 11:48:53 volumio volumio[909]: info: Getting Spotify volume May 02 11:48:53 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:53 volumio volumio[909]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 02 11:48:53 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 24) May 02 11:48:53 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 02 11:48:53 volumio volumio[909]: info: CoreCommandRouter::volumioGetState May 02 11:48:53 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:48:53 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 May 02 11:48:54 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:54 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:54 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 67. May 02 11:48:54 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:54 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:54 volumio go-librespot[2552]: Librespot-go daemon starting... May 02 11:48:54 volumio go-librespot[2552]: time="2024-05-02T11:48:54+02:00" level=info msg="generated new device id: c9e5c1380c17170922e6a240ceca1f8be8c1f538" May 02 11:48:54 volumio go-librespot[2552]: time="2024-05-02T11:48:54+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:54 volumio go-librespot[2552]: time="2024-05-02T11:48:54+02:00" level=debug msg="obtained new client token: AACht051diamKvtmchKDhNe8d2PHhKwRIam8EOYCfkHLAAwYxGPyn90956iDAN667DzTL9sgISG5lPdFSXyJW5/MRdEM8wn3pf4QJIpdGf7HaKPAMHK+mK31Ma58/7EphZFRKy8ht5vxEsYNQl8O3LzfbYx5XFc0TiLLjjC41HfSihIToUJTp46rLDMe2EToSa9c7BrYxO/Ug0htOvT12HETjQ4cZ0KRSf4+fk5tMdqFJBZ/RDyONVYdfpj/" May 02 11:48:54 volumio go-librespot[2552]: time="2024-05-02T11:48:54+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 02 11:48:54 volumio go-librespot[2552]: time="2024-05-02T11:48:54+02:00" level=debug msg="completed keyexchange" May 02 11:48:55 volumio go-librespot[2552]: time="2024-05-02T11:48:55+02:00" level=debug msg="completed challenge" May 02 11:48:55 volumio go-librespot[2552]: time="2024-05-02T11:48:55+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:48:56 volumio wpa_supplicant[825]: RRM: Ignoring radio measurement request: Not RRM network May 02 11:48:57 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:48:57 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:48:58 volumio volumio[909]: info: Preload queue cleared May 02 11:48:58 volumio volumio[909]: info: CoreCommandRouter::volumioReplaceandPlayItems May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::ClearQueue May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::stop May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:48:58 volumio volumio[909]: info: CorePlayQueue::clearPlayQueue May 02 11:48:58 volumio volumio[909]: info: CorePlayQueue::saveQueue May 02 11:48:58 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::addQueueItems May 02 11:48:58 volumio volumio[909]: info: CorePlayQueue::addQueueItems May 02 11:48:58 volumio volumio[909]: info: Preload queue cleared May 02 11:48:58 volumio volumio[909]: info: Adding Item to queue: upnp/folder/http://192.168.1.106:32469/ContentDirectory/737094ed-b28a-674c-d6a5-57e2f76bbd3d/control.xml@0f50c389959b24bd415d May 02 11:48:58 volumio volumio[909]: info: Exploding uri upnp/folder/http://192.168.1.106:32469/ContentDirectory/737094ed-b28a-674c-d6a5-57e2f76bbd3d/control.xml@0f50c389959b24bd415d in service upnp_browser May 02 11:48:58 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue May 02 11:48:58 volumio volumio[909]: info: CorePlayQueue::saveQueue May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::updateTrackBlock May 02 11:48:58 volumio volumio[909]: info: CorePlayQueue::getTrackBlock May 02 11:48:58 volumio volumio[909]: info: CoreCommandRouter::volumioPlay May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::play index 0 May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::stop May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::play index undefined May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:48:58 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:48:58 volumio volumio[909]: info: CoreStateMachine::startPlaybackTimer May 02 11:48:58 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:48:58 volumio volumio[909]: info: [1714643338393] ControllerUPNPBrowser::clearAddPlayTrack May 02 11:48:58 volumio volumio[909]: verbose: ControllerMpd::sendMpdCommand stop May 02 11:48:58 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:48:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 68. May 02 11:48:58 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:48:58 volumio systemd[1]: Started go-librespot Daemon. May 02 11:48:58 volumio go-librespot[2560]: Librespot-go daemon starting... May 02 11:48:58 volumio go-librespot[2560]: time="2024-05-02T11:48:58+02:00" level=info msg="generated new device id: a9e1f8d17ec28d79d1d9723e9e0c730313a0f508" May 02 11:48:58 volumio go-librespot[2560]: time="2024-05-02T11:48:58+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:48:58 volumio go-librespot[2560]: time="2024-05-02T11:48:58+02:00" level=debug msg="obtained new client token: AAB87YdeenfHIpQovbZpYiPoicEvM+03a9Ua8l/sXrQJIdZ7Kfi3E3VBtuQGOVo+LT52MHN/mckIwM9N8AWRkkjD+xoa5q5tsaVo2iCALxO7mSOCmNHGGqN9mFh8uPwZM7U7TntvOOD6ZIeXxlkUpu3Gl6eDa0xI6es9yLG9YhVxq7qJkjpgM9K5MBRbiSIUxhxSmZSUg1oYn8XlEuKv0noYqhN9+BuhMpC3DuKbEShUcgEQHbKz10Vo0ac/" May 02 11:48:59 volumio go-librespot[2560]: time="2024-05-02T11:48:59+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 02 11:48:59 volumio go-librespot[2560]: time="2024-05-02T11:48:59+02:00" level=debug msg="completed keyexchange" May 02 11:48:59 volumio go-librespot[2560]: time="2024-05-02T11:48:59+02:00" level=debug msg="completed challenge" May 02 11:48:59 volumio go-librespot[2560]: time="2024-05-02T11:48:59+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:48:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:48:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:49:00 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:00 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:49:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 69. May 02 11:49:02 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:49:02 volumio systemd[1]: Started go-librespot Daemon. May 02 11:49:02 volumio go-librespot[2569]: Librespot-go daemon starting... May 02 11:49:02 volumio go-librespot[2569]: time="2024-05-02T11:49:02+02:00" level=info msg="generated new device id: 254cc846d5e07dd1085aff831114847340cf4f70" May 02 11:49:02 volumio go-librespot[2569]: time="2024-05-02T11:49:02+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:49:03 volumio go-librespot[2569]: time="2024-05-02T11:49:03+02:00" level=debug msg="obtained new client token: AAAAd0H3rQ5Dx7bY8wuWcOjlU0OW/qWQhpxwxix5hR9V91582e2ko+tBB8DKMwO1qqrnC0W9ow8ayk8a6wPEBzT9UMzrYuSMk7BE3FPtiGZr687FaLAza10DF4MRjPRpV8H3Zm0PeRmjQUyJOpPoeC04E9HmmtZnsAW8Ss5fU9zLuclpd0G57Cd54AF+YsGzhHmwVg+7697jah2lauK5HUQ6YK1kZO463i24du0+Ij5pf31Ai2UxYJr0tw==" May 02 11:49:03 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:03 volumio go-librespot[2569]: time="2024-05-02T11:49:03+02:00" level=debug msg="new websocket client" May 02 11:49:03 volumio volumio[909]: info: Connection to go-librespot Websocket established May 02 11:49:03 volumio go-librespot[2569]: time="2024-05-02T11:49:03+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:49:03 volumio go-librespot[2569]: time="2024-05-02T11:49:03+02:00" level=debug msg="completed keyexchange" May 02 11:49:03 volumio go-librespot[2569]: time="2024-05-02T11:49:03+02:00" level=debug msg="completed challenge" May 02 11:49:03 volumio go-librespot[2569]: time="2024-05-02T11:49:03+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:49:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:49:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:49:03 volumio volumio[909]: info: Connection to go-librespot Websocket closed May 02 11:49:04 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:49:04 volumio volumio[909]: info: Preload queue cleared May 02 11:49:05 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:49:05 volumio volumio[909]: info: Preload queue cleared May 02 11:49:06 volumio volumio[909]: info: Getting Spotify volume May 02 11:49:06 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:06 volumio volumio[909]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 02 11:49:06 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 25) May 02 11:49:06 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 02 11:49:06 volumio volumio[909]: info: CoreCommandRouter::volumioGetState May 02 11:49:06 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:49:06 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 May 02 11:49:06 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:49:06 volumio volumio[909]: info: Preload queue cleared May 02 11:49:06 volumio volumio[909]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' May 02 11:49:06 volumio volumio[909]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' May 02 11:49:06 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:06 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:49:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 70. May 02 11:49:06 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:49:07 volumio systemd[1]: Started go-librespot Daemon. May 02 11:49:07 volumio go-librespot[2578]: Librespot-go daemon starting... May 02 11:49:07 volumio go-librespot[2578]: time="2024-05-02T11:49:07+02:00" level=info msg="generated new device id: 480ac405725d7a0394ee509b9a74d250d94a8ae7" May 02 11:49:07 volumio go-librespot[2578]: time="2024-05-02T11:49:07+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:49:07 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:49:07 volumio volumio[909]: info: Preload queue cleared May 02 11:49:07 volumio go-librespot[2578]: time="2024-05-02T11:49:07+02:00" level=debug msg="obtained new client token: AADmMGx9A74YiLhCqBt/OWflO5zcnjH8Kk11yG+a0NGlO8EhIaDo6cEEBqOK5Bv7y9y4b1jjWLGXNIB4X77YQr7sjB09XZFLheqGg8MRjJLhuYnwTySXnRBIZaLuwUM+dskkjwO5IUs5zkWvV+rmSDvWFkr2P/GU3PR4YbXjr0kQREQARVjwpAGg8o3WKeZJd3CTFErEr6IjRMDNe/IvH8BWKN4FmyAc83tBCmb+64XjMinluDuAQVbLIHzm" May 02 11:49:07 volumio go-librespot[2578]: time="2024-05-02T11:49:07+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:49:07 volumio go-librespot[2578]: time="2024-05-02T11:49:07+02:00" level=debug msg="completed keyexchange" May 02 11:49:08 volumio go-librespot[2578]: time="2024-05-02T11:49:08+02:00" level=debug msg="completed challenge" May 02 11:49:08 volumio go-librespot[2578]: time="2024-05-02T11:49:08+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:49:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:49:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:49:08 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:49:09 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:09 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:49:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 71. May 02 11:49:11 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:49:11 volumio systemd[1]: Started go-librespot Daemon. May 02 11:49:11 volumio go-librespot[2587]: Librespot-go daemon starting... May 02 11:49:11 volumio go-librespot[2587]: time="2024-05-02T11:49:11+02:00" level=info msg="generated new device id: 4399d901b3d5de10a6ecac5799f064df9353925c" May 02 11:49:11 volumio go-librespot[2587]: time="2024-05-02T11:49:11+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:49:11 volumio go-librespot[2587]: time="2024-05-02T11:49:11+02:00" level=debug msg="obtained new client token: AAB7qYI2Guy0KY+41G/z8MKCZbhsjyBEvqAdE8+0NqZEAWSEVqbkyySOOrzMK7T2cIrUiM9l8eWy5ANNETQ0L3wRFDdGILw8c0yihjjh9X3/DsE2I7aub7CyF6QZANlhid2C5sBzH+EsCqI6evorVSzEO8Zzy6Z2UX9buuH8AkP6YIJxmrVQY//dooElcMJ+azNrg4DGt6WdHIn+vy6JmSipx6x1R2InNFbmMJwhTAsg2Wcbrc2yUOS5t8EY" May 02 11:49:11 volumio volumio[909]: info: Preload queue cleared May 02 11:49:11 volumio go-librespot[2587]: time="2024-05-02T11:49:11+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:49:11 volumio go-librespot[2587]: time="2024-05-02T11:49:11+02:00" level=debug msg="completed keyexchange" May 02 11:49:12 volumio go-librespot[2587]: time="2024-05-02T11:49:12+02:00" level=debug msg="completed challenge" May 02 11:49:12 volumio go-librespot[2587]: time="2024-05-02T11:49:12+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:49:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:49:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:49:12 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:12 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:13 volumio volumio[909]: info: Preload queue cleared May 02 11:49:13 volumio volumio[909]: info: CoreCommandRouter::volumioReplaceandPlayItems May 02 11:49:13 volumio volumio[909]: info: CoreStateMachine::ClearQueue May 02 11:49:13 volumio volumio[909]: info: CoreStateMachine::stop May 02 11:49:13 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:49:13 volumio volumio[909]: info: CorePlayQueue::clearPlayQueue May 02 11:49:13 volumio volumio[909]: info: CorePlayQueue::saveQueue May 02 11:49:13 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue May 02 11:49:13 volumio volumio[909]: info: CoreStateMachine::addQueueItems May 02 11:49:13 volumio volumio[909]: info: CorePlayQueue::addQueueItems May 02 11:49:13 volumio volumio[909]: info: Preload queue cleared May 02 11:49:13 volumio volumio[909]: info: Adding Item to queue: upnp/folder/http://192.168.1.106:32469/ContentDirectory/737094ed-b28a-674c-d6a5-57e2f76bbd3d/control.xml@3c05747fc3827cb387c2 May 02 11:49:13 volumio volumio[909]: info: Exploding uri upnp/folder/http://192.168.1.106:32469/ContentDirectory/737094ed-b28a-674c-d6a5-57e2f76bbd3d/control.xml@3c05747fc3827cb387c2 in service upnp_browser May 02 11:49:14 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue May 02 11:49:14 volumio volumio[909]: info: CorePlayQueue::saveQueue May 02 11:49:14 volumio volumio[909]: info: CoreStateMachine::updateTrackBlock May 02 11:49:14 volumio volumio[909]: info: CorePlayQueue::getTrackBlock May 02 11:49:14 volumio volumio[909]: info: CoreCommandRouter::volumioPlay May 02 11:49:14 volumio volumio[909]: info: CoreStateMachine::play index 0 May 02 11:49:14 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:49:14 volumio volumio[909]: info: CoreStateMachine::stop May 02 11:49:14 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:49:14 volumio volumio[909]: info: CoreStateMachine::play index undefined May 02 11:49:14 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 11:49:14 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:49:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:49:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 72. May 02 11:49:15 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:49:15 volumio systemd[1]: Started go-librespot Daemon. May 02 11:49:15 volumio go-librespot[2595]: Librespot-go daemon starting... May 02 11:49:15 volumio go-librespot[2595]: time="2024-05-02T11:49:15+02:00" level=info msg="generated new device id: 3da98f843d2062a90db6bae626d1a72499533ec7" May 02 11:49:15 volumio go-librespot[2595]: time="2024-05-02T11:49:15+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:49:15 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:15 volumio go-librespot[2595]: time="2024-05-02T11:49:15+02:00" level=debug msg="new websocket client" May 02 11:49:15 volumio volumio[909]: info: Connection to go-librespot Websocket established May 02 11:49:16 volumio go-librespot[2595]: time="2024-05-02T11:49:16+02:00" level=debug msg="obtained new client token: AADl5teiwDQf5jJz7SQhwEONYQ5+4W+FRNjTOGpxYaT7lVUXwvnj80Wlq/0SUVFUYCqhay7rUPo+GkfM3M7aWFkU2PsslEl/wtg5rjFOUtKgSHgtgPUSjYKzN2tnnXSOy0KhtkObuvdFuhQjBxOTBumBcuKoleqftuhR0uqFkXVzpNlb0v6q+eYhmNnNh63nwpDYm27dhVTkS1bk5bu/B2DZfXmJEvjlHAw/Utgk7GupMHsVykdCmTN8Tw==" May 02 11:49:16 volumio go-librespot[2595]: time="2024-05-02T11:49:16+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 02 11:49:16 volumio go-librespot[2595]: time="2024-05-02T11:49:16+02:00" level=debug msg="completed keyexchange" May 02 11:49:16 volumio go-librespot[2595]: time="2024-05-02T11:49:16+02:00" level=debug msg="completed challenge" May 02 11:49:16 volumio go-librespot[2595]: time="2024-05-02T11:49:16+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:49:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:49:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:49:16 volumio volumio[909]: info: Connection to go-librespot Websocket closed May 02 11:49:18 volumio volumio[909]: info: Getting Spotify volume May 02 11:49:18 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:18 volumio volumio[909]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 02 11:49:18 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 26) May 02 11:49:18 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 02 11:49:19 volumio volumio[909]: info: CoreCommandRouter::volumioGetState May 02 11:49:19 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:49:19 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 May 02 11:49:19 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:19 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:49:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 73. May 02 11:49:19 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:49:20 volumio systemd[1]: Started go-librespot Daemon. May 02 11:49:20 volumio go-librespot[2604]: Librespot-go daemon starting... May 02 11:49:20 volumio go-librespot[2604]: time="2024-05-02T11:49:20+02:00" level=info msg="generated new device id: 06c20a47a6edcda57c2489ad8c8c99ccb2c8ea3e" May 02 11:49:20 volumio go-librespot[2604]: time="2024-05-02T11:49:20+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:49:20 volumio go-librespot[2604]: time="2024-05-02T11:49:20+02:00" level=debug msg="obtained new client token: AADcFvGBdbgSr+nU0uTi2GKXiQkZ49tUkrkvePIakSNLArk/5uUY/qHq5xnZSntDrNIThcumfXnOgq7G78Z4/0GN1TNoZ2HnunXhrji1cFIE+/wq+xUpzcgwYplqLJfT8ul8KexTFy1sxMhz4iw7MEBdq1U0JhmM9cRcqDBlASnB0r8c+86QpW1if5A2IuJ4BnZwqnqNazu5/UP98TdoPi7FTpfA/HznkpaYx7XDVHvf6Px0xFKDFgD3st6E" May 02 11:49:20 volumio go-librespot[2604]: time="2024-05-02T11:49:20+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:49:20 volumio go-librespot[2604]: time="2024-05-02T11:49:20+02:00" level=debug msg="completed keyexchange" May 02 11:49:21 volumio go-librespot[2604]: time="2024-05-02T11:49:21+02:00" level=debug msg="completed challenge" May 02 11:49:21 volumio go-librespot[2604]: time="2024-05-02T11:49:21+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:49:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:49:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:49:22 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:22 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:24 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:49:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 74. May 02 11:49:24 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:49:24 volumio systemd[1]: Started go-librespot Daemon. May 02 11:49:24 volumio go-librespot[2612]: Librespot-go daemon starting... May 02 11:49:24 volumio go-librespot[2612]: time="2024-05-02T11:49:24+02:00" level=info msg="generated new device id: b868face7db172e812f3dcf09b379788b599bf14" May 02 11:49:24 volumio go-librespot[2612]: time="2024-05-02T11:49:24+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:49:24 volumio go-librespot[2612]: time="2024-05-02T11:49:24+02:00" level=debug msg="obtained new client token: AABkPkCBGQdlte5wwRCncNHUX2rjeTmtumWnjkH6LUTbISyoWpNTUJhuMO1toQT3rRgFeTmy7zgI6a6+krEw7qbh4Ly/ASyBaHnc/Z8bBBlZGgZMdIzrcpip9VNIpFopaO59lAHehyNlZ2rqbgmRBIxvUNDXzvMazrGQWDzc7nafkuBjyoKZsroq4q8plEyin0brZLD0mQ8BAG7uCadQQ3yhKVVj1W/H5nOiN/jNspsEf4yvhkCp99s81DyZ" May 02 11:49:24 volumio go-librespot[2612]: time="2024-05-02T11:49:24+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:49:24 volumio go-librespot[2612]: time="2024-05-02T11:49:24+02:00" level=debug msg="completed keyexchange" May 02 11:49:25 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:49:25 volumio volumio[909]: info: Preload queue cleared May 02 11:49:25 volumio go-librespot[2612]: time="2024-05-02T11:49:25+02:00" level=debug msg="completed challenge" May 02 11:49:25 volumio go-librespot[2612]: time="2024-05-02T11:49:25+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:49:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:49:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:49:25 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:49:25 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:25 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:26 volumio volumio[909]: info: Preload queue cleared May 02 11:49:27 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:49:27 volumio volumio[909]: info: Preload queue cleared May 02 11:49:28 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:49:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 75. May 02 11:49:28 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:49:28 volumio systemd[1]: Started go-librespot Daemon. May 02 11:49:28 volumio go-librespot[2620]: Librespot-go daemon starting... May 02 11:49:28 volumio go-librespot[2620]: time="2024-05-02T11:49:28+02:00" level=info msg="generated new device id: 8f53287fe70e750961c83ea215c658069c3e03ae" May 02 11:49:28 volumio go-librespot[2620]: time="2024-05-02T11:49:28+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:49:28 volumio go-librespot[2620]: time="2024-05-02T11:49:28+02:00" level=debug msg="obtained new client token: AACNynJ3OQI7n5VUEwGC3l5VWZZCM+O2OhzEs5CCfl8EKvpNK+ojoyVtmeeuNVidmJs4ovBjyR0CYTHSo6/vmqVJLklmmfSIiDGV3ks919TvNVk++kCoHNjeudzTZy+fchVTAtwg9MbohiB3bmAJkgbbdGIiRSx0jrXKIPz9N1RbCc1YqeKSXCV2a9uEDgh7REQ6mGVMc7v8L3J0lgc3/XPu+LpttTeLw2wEcDWgBg6BhCb/iMqTwNwyKsiO" May 02 11:49:28 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:28 volumio volumio[909]: info: Connection to go-librespot Websocket established May 02 11:49:28 volumio go-librespot[2620]: time="2024-05-02T11:49:28+02:00" level=debug msg="new websocket client" May 02 11:49:29 volumio go-librespot[2620]: time="2024-05-02T11:49:29+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 02 11:49:29 volumio go-librespot[2620]: time="2024-05-02T11:49:29+02:00" level=debug msg="completed keyexchange" May 02 11:49:29 volumio go-librespot[2620]: time="2024-05-02T11:49:29+02:00" level=debug msg="completed challenge" May 02 11:49:29 volumio go-librespot[2620]: time="2024-05-02T11:49:29+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 02 11:49:29 volumio volumio[909]: info: Connection to go-librespot Websocket closed May 02 11:49:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 02 11:49:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 02 11:49:31 volumio volumio[909]: info: Getting Spotify volume May 02 11:49:31 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:31 volumio volumio[909]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 02 11:49:31 volumio volumio[909]: (node:909) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 27) May 02 11:49:31 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 02 11:49:32 volumio volumio[909]: info: CoreCommandRouter::volumioGetState May 02 11:49:32 volumio volumio[909]: info: CorePlayQueue::getTrack 0 May 02 11:49:32 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 May 02 11:49:32 volumio wpa_supplicant[825]: RRM: Ignoring radio measurement request: Not RRM network May 02 11:49:32 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 02 11:49:32 volumio volumio[909]: error: Upnp client error: Error: connect ECONNREFUSED 127.0.0.1:6600 May 02 11:49:32 volumio volumio[909]: info: Initializing connection to go-librespot Websocket May 02 11:49:32 volumio volumio[909]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 02 11:49:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 02 11:49:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 76. May 02 11:49:32 volumio systemd[1]: Stopped go-librespot Daemon. May 02 11:49:32 volumio systemd[1]: Started go-librespot Daemon. May 02 11:49:32 volumio go-librespot[2628]: Librespot-go daemon starting... May 02 11:49:32 volumio go-librespot[2628]: time="2024-05-02T11:49:32+02:00" level=info msg="generated new device id: 3bf7a1e0d953263abc08446c5dedbe241443c1a2" May 02 11:49:32 volumio go-librespot[2628]: time="2024-05-02T11:49:32+02:00" level=debug msg="stored credentials found for 11141246516" May 02 11:49:32 volumio volumio[909]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 02 11:49:32 volumio volumio[909]: TypeError: Cannot read property 'length' of undefined May 02 11:49:32 volumio volumio[909]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 May 02 11:49:32 volumio volumio[909]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 May 02 11:49:32 volumio volumio[909]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) May 02 11:49:32 volumio volumio[909]: at Parser.emit (events.js:315:20) May 02 11:49:32 volumio volumio[909]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) May 02 11:49:32 volumio volumio[909]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) May 02 11:49:32 volumio volumio[909]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) May 02 11:49:32 volumio volumio[909]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) May 02 11:49:32 volumio volumio[909]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) May 02 11:49:32 volumio volumio[909]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) May 02 11:49:32 volumio volumio[909]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) May 02 11:49:32 volumio volumio[909]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) May 02 11:49:32 volumio volumio[909]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) May 02 11:49:32 volumio volumio[909]: at IncomingMessage.emit (events.js:327:22) May 02 11:49:32 volumio volumio[909]: at endReadableNT (internal/streams/readable.js:1327:12) May 02 11:49:32 volumio volumio[909]: at processTicksAndRejections (internal/process/task_queues.js:80:21) May 02 11:49:32 volumio volumio[909]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 02 11:49:33 volumio go-librespot[2628]: time="2024-05-02T11:49:33+02:00" level=debug msg="obtained new client token: AACsvPd/tUjrUGnCFKazZqXHZTcaUfcxrXHjeEDA7AhuslGBvsJ4EWbEHXljdXB3tTkKt9dn5rlgVcg9+frI7mdU3DThNmn+N/fW0O7/NYmZzT1I24nu6gJxNqf5s4ifYaUBqJrUaghvEyadMdSxtbcajkuZ6pFTzzGOzxgz1ckDRZHAaZ8AOufRd5oSZfQsCLcaDAzUvZvF35KjE3HUXOf8WIwQ2M7mKnnxy/DDQrRYzK4g6Bn12y/wKg==" May 02 11:49:33 volumio go-librespot[2628]: time="2024-05-02T11:49:33+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 02 11:49:33 volumio sudo[2645]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-02 11:48 May 02 11:49:33 volumio sudo[2645]: 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"