-- Logs begin at Sat 2024-07-20 20:35:33 BST, end at Sat 2024-07-20 21:57:15 BST. -- Jul 20 21:56:01 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:01 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1467. Jul 20 21:56:02 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:02 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:02 minidsp-shd go-librespot[29789]: Librespot-go daemon starting... Jul 20 21:56:02 minidsp-shd go-librespot[29789]: time="2024-07-20T21:56:02+01:00" level=info msg="generated new device id: 45555aac3146bc8c5e1b5a8420ebac15aff2a148" Jul 20 21:56:02 minidsp-shd go-librespot[29789]: time="2024-07-20T21:56:02+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:02 minidsp-shd go-librespot[29789]: time="2024-07-20T21:56:02+01:00" level=debug msg="obtained new client token: AADNknegOuSayFhvn0xdKSTQpFNZdkHdtVRvdw3bGtTHp3ctAaXjm2TYlZQvfJ641DorCE7tewb1bQOs8R8S1G1E+dry7F/RZV+faKH+7z3m+QHbagBdT4ZbAyJm1I17pRY5krfGmQOVajfR54WnO7KdqBy6+UKfchcXkBImXBATnacZhp+jAWYnqmiUkSPEfbLZJHUhuQ5C0TxAG0f78t3ukeslOM5JNpDf++/vPeqJyDTCFvHTbFwuxGLA7S0=" Jul 20 21:56:02 minidsp-shd go-librespot[29789]: time="2024-07-20T21:56:02+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 20 21:56:03 minidsp-shd go-librespot[29789]: time="2024-07-20T21:56:03+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:03 minidsp-shd go-librespot[29789]: time="2024-07-20T21:56:03+01:00" level=debug msg="completed challenge" Jul 20 21:56:03 minidsp-shd go-librespot[29789]: time="2024-07-20T21:56:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:03 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:03 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:04 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:04 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1468. Jul 20 21:56:06 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:06 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:06 minidsp-shd go-librespot[29806]: Librespot-go daemon starting... Jul 20 21:56:06 minidsp-shd go-librespot[29806]: time="2024-07-20T21:56:06+01:00" level=info msg="generated new device id: 78fbbb8e4c6faca796a8fef100f1a295d7154213" Jul 20 21:56:06 minidsp-shd go-librespot[29806]: time="2024-07-20T21:56:06+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:07 minidsp-shd go-librespot[29806]: time="2024-07-20T21:56:07+01:00" level=debug msg="obtained new client token: AADRtU+sS4JPWHT5QQKmVYzJ1I0KkCWCztKI4gMqVueI2NVq4t8NEGU9ZEEgQsAi7qyqC6s7P4G8AKOJE3OaF2V143SwkwR6uXA3E9Nkxd8O4hSjFqzXJYbxjUvTg8WUexRMHELkz7oATeV4sNex/q0w6oeR0Yjj5Gql1WrkJNBVGQUxfm2K6B8SH/LX1u60f9HtLzdsB+tMl65kqqE18Iku+ZLFznvUR6uKwCU+a5fP0jGSyuiH4i9dt98S" Jul 20 21:56:07 minidsp-shd go-librespot[29806]: time="2024-07-20T21:56:07+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:07 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:07 minidsp-shd go-librespot[29806]: time="2024-07-20T21:56:07+01:00" level=debug msg="new websocket client" Jul 20 21:56:07 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket established Jul 20 21:56:07 minidsp-shd go-librespot[29806]: time="2024-07-20T21:56:07+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:07 minidsp-shd go-librespot[29806]: time="2024-07-20T21:56:07+01:00" level=debug msg="completed challenge" Jul 20 21:56:07 minidsp-shd go-librespot[29806]: time="2024-07-20T21:56:07+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:07 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket closed Jul 20 21:56:10 minidsp-shd volumio[712]: info: Getting Spotify volume Jul 20 21:56:10 minidsp-shd volumio[712]: (node:712) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:10 minidsp-shd volumio[712]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 20 21:56:10 minidsp-shd volumio[712]: (node:712) 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: 490) Jul 20 21:56:10 minidsp-shd volumio[712]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Jul 20 21:56:10 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetState Jul 20 21:56:10 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:10 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:10 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:10 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:10 minidsp-shd volumio[712]: info: Executing endpoint metavolumio Jul 20 21:56:10 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 20 21:56:10 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:10 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1469. Jul 20 21:56:11 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:11 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:11 minidsp-shd go-librespot[29824]: Librespot-go daemon starting... Jul 20 21:56:11 minidsp-shd go-librespot[29824]: time="2024-07-20T21:56:11+01:00" level=info msg="generated new device id: 7b09d0f5b35ea97f54a3cd632b6360ea66529944" Jul 20 21:56:11 minidsp-shd go-librespot[29824]: time="2024-07-20T21:56:11+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:11 minidsp-shd volumio[712]: info: Executing endpoint metavolumio Jul 20 21:56:11 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 20 21:56:11 minidsp-shd go-librespot[29824]: time="2024-07-20T21:56:11+01:00" level=debug msg="obtained new client token: AADOdX5MS6b4/QEaJKZd/HAjy84ekYce3fM8unFbeYgL2XP3k14KObnwligIF4g9ks5P5Af0zOh+RMtnGdSEpGtvSi8sQCgK/inTL9Onuev0u1eY5lAH9ScVBntc9iWWW7LMva1G9vBx4rl2BT0N1T6CUwWMvXQSWV4Jl78bAF4kMYeTQ0u4BAQPNjum7Kp+x7k3Ef3mumu9jL49upXTCqnjquK/pNWhitJe5Hqzlxcl+Cn5XzQuD1UWHhvmaRw=" Jul 20 21:56:11 minidsp-shd go-librespot[29824]: time="2024-07-20T21:56:11+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:11 minidsp-shd go-librespot[29824]: time="2024-07-20T21:56:11+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:11 minidsp-shd volumio[712]: info: Executing endpoint metavolumio Jul 20 21:56:11 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 20 21:56:12 minidsp-shd go-librespot[29824]: time="2024-07-20T21:56:12+01:00" level=debug msg="completed challenge" Jul 20 21:56:12 minidsp-shd go-librespot[29824]: time="2024-07-20T21:56:12+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:12 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:12 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:13 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:13 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1470. Jul 20 21:56:15 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:15 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:15 minidsp-shd go-librespot[29840]: Librespot-go daemon starting... Jul 20 21:56:15 minidsp-shd go-librespot[29840]: time="2024-07-20T21:56:15+01:00" level=info msg="generated new device id: fb4d1207dc1f5c95f4172c348cee2d8d8f0ee48b" Jul 20 21:56:15 minidsp-shd go-librespot[29840]: time="2024-07-20T21:56:15+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:15 minidsp-shd go-librespot[29840]: time="2024-07-20T21:56:15+01:00" level=debug msg="obtained new client token: AADpsGQZbsRn2DxdVVD+nqSAkHTmZJV4l8LCniVkNmBJQgld+QeHJpnq7MxFEZ5TrFX2D0xDo5NkYiibrPduxG+n3UVNAMEBRZOZqcLG5xjEi0+Nf3JnddHQv9R3Vdy7LoKYUWUw/EhuwXZcOujoTnuY/jh2+2+kdpXWwwKdG/R94RXH4Ct7LcQhLp2Uoof95cfuNpjvazgeagvGWHm5fbm9HkqOhB9y2qSYm0nby64no6cIS/0Lr1bFQyrIx6E=" Jul 20 21:56:15 minidsp-shd go-librespot[29840]: time="2024-07-20T21:56:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:15 minidsp-shd go-librespot[29840]: time="2024-07-20T21:56:15+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:16 minidsp-shd go-librespot[29840]: time="2024-07-20T21:56:16+01:00" level=debug msg="completed challenge" Jul 20 21:56:16 minidsp-shd go-librespot[29840]: time="2024-07-20T21:56:16+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:16 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:16 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:16 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:16 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:19 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:19 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1471. Jul 20 21:56:19 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:19 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:19 minidsp-shd go-librespot[29856]: Librespot-go daemon starting... Jul 20 21:56:19 minidsp-shd go-librespot[29856]: time="2024-07-20T21:56:19+01:00" level=info msg="generated new device id: f3382ee01ac92cb80b76ee27400c16544fbfb568" Jul 20 21:56:19 minidsp-shd go-librespot[29856]: time="2024-07-20T21:56:19+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:19 minidsp-shd go-librespot[29856]: time="2024-07-20T21:56:19+01:00" level=debug msg="obtained new client token: AAAAko1hYIzU6DtKuO61r3dpFRqMmIzy2RhEPcL24Ti6ShkdiCuKGGYpNm6ONlZGdtRPEYMwGMW3AazeIj6Rl9p6YZHUKSi3IF+wUBqAfN5rf0sfBnw3Zua+OoA/dbXPs9V1ekR7dvneZUkKwCP0aJSWJfxQvaf/c6ok0qh7Lae6519E2UpNzsDR9i2rc6TSRrToHtPnzaLy/5P846FBlb+x/ffLTx5utD2hBcjJHKJsaXXvsLez0veQ4jGPMtk=" Jul 20 21:56:19 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:19 minidsp-shd go-librespot[29856]: time="2024-07-20T21:56:19+01:00" level=debug msg="new websocket client" Jul 20 21:56:19 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket established Jul 20 21:56:19 minidsp-shd go-librespot[29856]: time="2024-07-20T21:56:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:20 minidsp-shd go-librespot[29856]: time="2024-07-20T21:56:20+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:20 minidsp-shd go-librespot[29856]: time="2024-07-20T21:56:20+01:00" level=debug msg="completed challenge" Jul 20 21:56:20 minidsp-shd go-librespot[29856]: time="2024-07-20T21:56:20+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:20 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:20 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:20 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket closed Jul 20 21:56:22 minidsp-shd volumio[712]: info: Getting Spotify volume Jul 20 21:56:22 minidsp-shd volumio[712]: (node:712) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:22 minidsp-shd volumio[712]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 20 21:56:22 minidsp-shd volumio[712]: (node:712) 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: 491) Jul 20 21:56:22 minidsp-shd volumio[712]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Jul 20 21:56:22 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetState Jul 20 21:56:22 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:22 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:22 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:22 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:23 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:23 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:23 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:23 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1472. Jul 20 21:56:23 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:23 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:23 minidsp-shd go-librespot[29873]: Librespot-go daemon starting... Jul 20 21:56:23 minidsp-shd go-librespot[29873]: time="2024-07-20T21:56:23+01:00" level=info msg="generated new device id: dffbc00025b1264d3cfb57e477da818cf91e4f59" Jul 20 21:56:23 minidsp-shd go-librespot[29873]: time="2024-07-20T21:56:23+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:24 minidsp-shd go-librespot[29873]: time="2024-07-20T21:56:24+01:00" level=debug msg="obtained new client token: AACIk6fvfegr/buYHOGqYm6EcFcjqmQM51c3df7nRuS8EjU49lerRgdmE56x4j8JM4d3dg7ciDBDyprGd0WmoOwxf9BIsyN/Q63C+y34oowxuqJG9GFpYy5bnLqkVVEGO34j8nB9HVmxKv2mJHPxyAicOFrH3G0weJcmqfc4leRgjzU1tFKUY0zkiHWQAWHdbflyLfVkAbWOSQuddPvDXhjIaJ5sNW+c6z0uTrEVct+P46/lJQIpFlAJezlc" Jul 20 21:56:24 minidsp-shd go-librespot[29873]: time="2024-07-20T21:56:24+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 20 21:56:24 minidsp-shd go-librespot[29873]: time="2024-07-20T21:56:24+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:24 minidsp-shd go-librespot[29873]: time="2024-07-20T21:56:24+01:00" level=debug msg="completed challenge" Jul 20 21:56:24 minidsp-shd go-librespot[29873]: time="2024-07-20T21:56:24+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:26 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:26 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:28 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:28 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1473. Jul 20 21:56:28 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:28 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:28 minidsp-shd go-librespot[29889]: Librespot-go daemon starting... Jul 20 21:56:28 minidsp-shd go-librespot[29889]: time="2024-07-20T21:56:28+01:00" level=info msg="generated new device id: 6109686fd951978ca55fa8c396d21010334ba002" Jul 20 21:56:28 minidsp-shd go-librespot[29889]: time="2024-07-20T21:56:28+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:28 minidsp-shd go-librespot[29889]: time="2024-07-20T21:56:28+01:00" level=debug msg="obtained new client token: AAAxtufSf/wPPfa/gnblg8lcbBsRxx9O3MwbX7vj9WWWYl1kfUP9n4BLsLuJEr+XyrTWpYXjipyDbgS0ZEjI3JiXhqrI6W0mj/0cv/GBD6kFWrTBsWhzAbbV/WbWt+ZDlU1qhaINGFPiaPWpB4HUymMJZ5Eazun/6OgZCgBGLWZZIAHpvZlwgWe+hoq7EJ1M6zkmDbVLdSVJ3OWiids2UXi9LT2jMLZWyAOQbGraiPICj9UtB6OHXigUvFGNoog=" Jul 20 21:56:28 minidsp-shd go-librespot[29889]: time="2024-07-20T21:56:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:28 minidsp-shd go-librespot[29889]: time="2024-07-20T21:56:28+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:29 minidsp-shd go-librespot[29889]: time="2024-07-20T21:56:29+01:00" level=debug msg="completed challenge" Jul 20 21:56:29 minidsp-shd go-librespot[29889]: time="2024-07-20T21:56:29+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:29 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:29 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:29 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:29 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:32 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:32 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1474. Jul 20 21:56:32 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:32 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:32 minidsp-shd go-librespot[29944]: Librespot-go daemon starting... Jul 20 21:56:32 minidsp-shd go-librespot[29944]: time="2024-07-20T21:56:32+01:00" level=info msg="generated new device id: 5145b3276c8316042796f6f312b7cde1373dac00" Jul 20 21:56:32 minidsp-shd go-librespot[29944]: time="2024-07-20T21:56:32+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:32 minidsp-shd go-librespot[29944]: time="2024-07-20T21:56:32+01:00" level=debug msg="obtained new client token: AABt8IzkotUkLo/u2/0+picuFai00uUjGC/k3oPei7cn4XqWKCAmRJnebbUQcu0LKXyCJ9gt62+1KNbtJxL3cah0tDFQka55kSE53yrrhHpJs1L4/yy/jgumqbzW5DLTg/NWxfLsksGtYBcKH9o8Ea0263pRiqMDXQJCa+HkBrCYJ68gn3vsYNTkW95UeLVmHwPSJCCVyPF5glvQL/xMXSTCNj8Zk/SGMU7T4kgeyGZS2K34YcXuk60La13TG1c=" Jul 20 21:56:32 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:32 minidsp-shd go-librespot[29944]: time="2024-07-20T21:56:32+01:00" level=debug msg="new websocket client" Jul 20 21:56:32 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket established Jul 20 21:56:32 minidsp-shd go-librespot[29944]: time="2024-07-20T21:56:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:32 minidsp-shd go-librespot[29944]: time="2024-07-20T21:56:32+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:33 minidsp-shd go-librespot[29944]: time="2024-07-20T21:56:33+01:00" level=debug msg="completed challenge" Jul 20 21:56:33 minidsp-shd go-librespot[29944]: time="2024-07-20T21:56:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:33 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:33 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:33 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket closed Jul 20 21:56:35 minidsp-shd volumio[712]: info: Getting Spotify volume Jul 20 21:56:35 minidsp-shd volumio[712]: (node:712) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:35 minidsp-shd volumio[712]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 20 21:56:35 minidsp-shd volumio[712]: (node:712) 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: 492) Jul 20 21:56:35 minidsp-shd volumio[712]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Jul 20 21:56:35 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetState Jul 20 21:56:35 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:35 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:35 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:35 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:36 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:36 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1475. Jul 20 21:56:36 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:36 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:36 minidsp-shd go-librespot[29962]: Librespot-go daemon starting... Jul 20 21:56:36 minidsp-shd go-librespot[29962]: time="2024-07-20T21:56:36+01:00" level=info msg="generated new device id: 7dcb1775f1da681bcfe91b8e0a1d16ceac647844" Jul 20 21:56:36 minidsp-shd go-librespot[29962]: time="2024-07-20T21:56:36+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:36 minidsp-shd go-librespot[29962]: time="2024-07-20T21:56:36+01:00" level=debug msg="obtained new client token: AAAnQ+bAB3GFQua+PMnqUeuQbRxtaEwCEJqL9VcApftDvN2uEW9OFqaXTPmYgS1EwHcKc860XuOHlaopLqDtSskqTlRmVp4ZSUUeWZXSJ6klIlfFYxw1h7lN9zFOFlZ2zgV8+KKHQhEzhqTkXjKSzOSbQufL8/crlsKLwuXGv1FHuRObQY1/N1QAHHAUP1KcTq/04imyFBtbDBCavxLmSrRY9ILQR0IPDarfkKuJN6zjNTyAwa87FRhvxJsYuxY=" Jul 20 21:56:36 minidsp-shd go-librespot[29962]: time="2024-07-20T21:56:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:37 minidsp-shd go-librespot[29962]: time="2024-07-20T21:56:37+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:37 minidsp-shd go-librespot[29962]: time="2024-07-20T21:56:37+01:00" level=debug msg="completed challenge" Jul 20 21:56:37 minidsp-shd go-librespot[29962]: time="2024-07-20T21:56:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:37 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:37 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:39 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:39 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:40 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:40 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1476. Jul 20 21:56:40 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:40 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:40 minidsp-shd go-librespot[29978]: Librespot-go daemon starting... Jul 20 21:56:40 minidsp-shd go-librespot[29978]: time="2024-07-20T21:56:40+01:00" level=info msg="generated new device id: 2b520554c8593b77dd12e28f65b9de347af6bfde" Jul 20 21:56:40 minidsp-shd go-librespot[29978]: time="2024-07-20T21:56:40+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:41 minidsp-shd go-librespot[29978]: time="2024-07-20T21:56:41+01:00" level=debug msg="obtained new client token: AAAjvseRc5GElJTyJftUW8h1btmJncEqLZohoLEzelzo8jhWjNM6FfhqTDSdStQgAvvVnJiMv9UPlSxkmlQnH/eX+zMN5uDPcMfls2a5mQITiMFTJO554UfFgv5I4wb+e6MeMGWN0P/rDJOMvXs9CVoUdZ5CHRIT3egi46HY/ONmoX32ilhTAtN7Y0hpTtDMpCceAJpC4XkfmvOaQMIi4myGHXxv5epJWm0zpXCgO5/D7Y61qGnyp8Yv+AzK" Jul 20 21:56:41 minidsp-shd go-librespot[29978]: time="2024-07-20T21:56:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:41 minidsp-shd go-librespot[29978]: time="2024-07-20T21:56:41+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:41 minidsp-shd go-librespot[29978]: time="2024-07-20T21:56:41+01:00" level=debug msg="completed challenge" Jul 20 21:56:41 minidsp-shd go-librespot[29978]: time="2024-07-20T21:56:41+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:41 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:41 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:42 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:42 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:45 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:45 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1477. Jul 20 21:56:45 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:45 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:45 minidsp-shd go-librespot[29995]: Librespot-go daemon starting... Jul 20 21:56:45 minidsp-shd go-librespot[29995]: time="2024-07-20T21:56:45+01:00" level=info msg="generated new device id: 1f1fc6247c5b76a791ac6f97c5611d9680d20db6" Jul 20 21:56:45 minidsp-shd go-librespot[29995]: time="2024-07-20T21:56:45+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:45 minidsp-shd go-librespot[29995]: time="2024-07-20T21:56:45+01:00" level=debug msg="obtained new client token: AAAtPuQIscfgJ2wUYuw+bJ4vq87ihpXBb+BcJL6cErteP3wPeNOVicFsQxSBC//yV1XM0ahi2or5gUmzHuwSYESHCG7FbWQ/8rr7bDaeanmSWZ7nzi1jSFx0LiZkIIj5JzYd5nQIPdvE5EISuGCa7M+IE61Fu8/eHS1jBmznuSdHluANDte9ztRJljdmyXlC7XxqtlbSN96niP7PIp/BiU7GkXxXwTvxjOSQMKy4skTUPWMDrhpQgU0c1UsqP3c=" Jul 20 21:56:45 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:45 minidsp-shd go-librespot[29995]: time="2024-07-20T21:56:45+01:00" level=debug msg="new websocket client" Jul 20 21:56:45 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket established Jul 20 21:56:45 minidsp-shd go-librespot[29995]: time="2024-07-20T21:56:45+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:45 minidsp-shd go-librespot[29995]: time="2024-07-20T21:56:45+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:46 minidsp-shd go-librespot[29995]: time="2024-07-20T21:56:46+01:00" level=debug msg="completed challenge" Jul 20 21:56:46 minidsp-shd go-librespot[29995]: time="2024-07-20T21:56:46+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:46 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:46 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:46 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket closed Jul 20 21:56:48 minidsp-shd volumio[712]: info: Getting Spotify volume Jul 20 21:56:48 minidsp-shd volumio[712]: (node:712) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:48 minidsp-shd volumio[712]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 20 21:56:48 minidsp-shd volumio[712]: (node:712) 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: 493) Jul 20 21:56:48 minidsp-shd volumio[712]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Jul 20 21:56:48 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetState Jul 20 21:56:48 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:48 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:48 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:48 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:49 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:49 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:49 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:49 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1478. Jul 20 21:56:49 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:49 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:49 minidsp-shd go-librespot[30011]: Librespot-go daemon starting... Jul 20 21:56:49 minidsp-shd go-librespot[30011]: time="2024-07-20T21:56:49+01:00" level=info msg="generated new device id: 2b6f826ae75784020ddc35a1067f8832aaf6f2cf" Jul 20 21:56:49 minidsp-shd go-librespot[30011]: time="2024-07-20T21:56:49+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:49 minidsp-shd go-librespot[30011]: time="2024-07-20T21:56:49+01:00" level=debug msg="obtained new client token: AAAhge0lluxnabpSY5RzwUnm7fnbdwuISUFHuLeQPsh0U64rbNK2NDpSaia1OuIYMjF12BLtylNG9J0tyPrsWrS+Rsc4ylFYq7Q1uenM8hZ5Y1oq5k11zM/rNcSoSMWRQGDz8pKi3vFIuBlcErLjjiFMgw7Loi8Rz8E1OYmxTqEhRe7tYSWztXK3Ip9koQ7ncesWvU53q/sYC79KPuFrpNrF2euRhW3lCygaKRcVqWkYbQ4cOcwsctzc7RLawZY=" Jul 20 21:56:49 minidsp-shd go-librespot[30011]: time="2024-07-20T21:56:49+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:49 minidsp-shd go-librespot[30011]: time="2024-07-20T21:56:49+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:50 minidsp-shd go-librespot[30011]: time="2024-07-20T21:56:50+01:00" level=debug msg="completed challenge" Jul 20 21:56:50 minidsp-shd go-librespot[30011]: time="2024-07-20T21:56:50+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:50 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:50 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:52 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:52 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:52 minidsp-shd volumio[712]: info: CorePlayQueue::getTrack 39 Jul 20 21:56:52 minidsp-shd volumio[712]: info: CorePlayQueue::getTrack 40 Jul 20 21:56:53 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:53 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1479. Jul 20 21:56:53 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:53 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:53 minidsp-shd go-librespot[30027]: Librespot-go daemon starting... Jul 20 21:56:53 minidsp-shd go-librespot[30027]: time="2024-07-20T21:56:53+01:00" level=info msg="generated new device id: 2730aa413bd9e2d787ec2d5ed9b39d2bd906ba2e" Jul 20 21:56:53 minidsp-shd go-librespot[30027]: time="2024-07-20T21:56:53+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:53 minidsp-shd go-librespot[30027]: time="2024-07-20T21:56:53+01:00" level=debug msg="obtained new client token: AADKgPsVHW9IiFiSy1ktVUp6h+nqMMUNTDFEJKtBVZ2cO78eSSYURg+zLqpoZjlCY2Gl8LRA2qhz2G9iAbqQpM6kxhUdYzRIG7/yt1w1ZlPbGw+oxWytoGsoWwht5hputU14pX0M84sxTiLATiI7qRjLMVgpXnuiDWVfqNqAwPngVrpphU0iGqIc+FsCU3EdZpNwtvDPOH7twE+4WYqiR/hp6dOj3mdxmEZag5ou2pYV9gy6gDTzpYYHpcApeok=" Jul 20 21:56:53 minidsp-shd go-librespot[30027]: time="2024-07-20T21:56:53+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:56:54 minidsp-shd go-librespot[30027]: time="2024-07-20T21:56:54+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:54 minidsp-shd go-librespot[30027]: time="2024-07-20T21:56:54+01:00" level=debug msg="completed challenge" Jul 20 21:56:54 minidsp-shd go-librespot[30027]: time="2024-07-20T21:56:54+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:54 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:54 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:55 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:55 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:56:57 minidsp-shd volumio[712]: info: Jul 20 21:56:57 minidsp-shd volumio[712]: ---------------------------- MPD announces state update: player Jul 20 21:56:57 minidsp-shd volumio[712]: info: ControllerMpd::getState Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: ControllerMpd::sendMpdCommand status Jul 20 21:56:57 minidsp-shd volumio[712]: info: Jul 20 21:56:57 minidsp-shd volumio[712]: ---------------------------- MPD announces state update: player Jul 20 21:56:57 minidsp-shd volumio[712]: info: ControllerMpd::getState Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: ControllerMpd::sendMpdCommand status Jul 20 21:56:57 minidsp-shd volumio[712]: info: Jul 20 21:56:57 minidsp-shd volumio[712]: ---------------------------- MPD announces state update: player Jul 20 21:56:57 minidsp-shd volumio[712]: info: ControllerMpd::getState Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: ControllerMpd::sendMpdCommand status Jul 20 21:56:57 minidsp-shd volumio[712]: info: sendMpdCommand status took 7 milliseconds Jul 20 21:56:57 minidsp-shd volumio[712]: info: sendMpdCommand status took 5 milliseconds Jul 20 21:56:57 minidsp-shd volumio[712]: info: sendMpdCommand status took 3 milliseconds Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: ControllerMpd::parseState Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: ControllerMpd::parseState Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: ControllerMpd::parseState Jul 20 21:56:57 minidsp-shd volumio[712]: info: ControllerMpd::pushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::servicePushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::pushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioPushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output update for this device Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output Jul 20 21:56:57 minidsp-shd volumio[712]: info: CorePlayQueue::getTrack 39 Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: CURRENT POSITION 39 Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::syncState stateService stop Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::syncState currentStatus play Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioPushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output update for this device Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::stPlaybackTimer Jul 20 21:56:57 minidsp-shd volumio[712]: info: ControllerMpd::pushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::servicePushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::pushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioPushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output update for this device Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output Jul 20 21:56:57 minidsp-shd volumio[712]: info: CorePlayQueue::getTrack 0 Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: CURRENT POSITION 0 Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::syncState stateService stop Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::syncState currentStatus stop Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::pushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioPushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output update for this device Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output Jul 20 21:56:57 minidsp-shd volumio[712]: info: No code Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::pushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioPushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output update for this device Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output Jul 20 21:56:57 minidsp-shd volumio[712]: info: ControllerMpd::pushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::servicePushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::pushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioPushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output update for this device Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output Jul 20 21:56:57 minidsp-shd volumio[712]: info: CorePlayQueue::getTrack 0 Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jul 20 21:56:57 minidsp-shd volumio[712]: verbose: CURRENT POSITION 0 Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::syncState stateService stop Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::syncState currentStatus stop Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::pushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioPushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output update for this device Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output Jul 20 21:56:57 minidsp-shd volumio[712]: info: No code Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreStateMachine::pushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioPushState Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output update for this device Jul 20 21:56:57 minidsp-shd volumio[712]: info: MRS: Pushing multiroomSync output Jul 20 21:56:57 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:56:57 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1480. Jul 20 21:56:57 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:56:57 minidsp-shd volumio[712]: info: ------------------------------ 70ms Jul 20 21:56:57 minidsp-shd volumio[712]: info: ------------------------------ 69ms Jul 20 21:56:57 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:56:57 minidsp-shd volumio[712]: info: ------------------------------ 69ms Jul 20 21:56:57 minidsp-shd go-librespot[30043]: Librespot-go daemon starting... Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:57 minidsp-shd go-librespot[30043]: time="2024-07-20T21:56:57+01:00" level=info msg="generated new device id: 5b6e251bae525a92184aa05050d40a5563a959ad" Jul 20 21:56:57 minidsp-shd go-librespot[30043]: time="2024-07-20T21:56:57+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:56:57 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:56:58 minidsp-shd go-librespot[30043]: time="2024-07-20T21:56:58+01:00" level=debug msg="obtained new client token: AAA0uBXXSImAWjZJ28+oaR20SHtJEJsdAZ39MJfkHxbP2RW5YfRmGoIB7DE2OwI3tzqZBuJRWO+Qg8UfSaV3jSVPJSCMrH/9QYQGhh1e+Rby7U9BL2YaMBuL0Y7OnKEwgcHlXopQYI7S+LeYWzbE0m1JJOSDB/Tscvoi7n3il3Bd10l/88XGsIFvkAf0Nt4XVkv1+mumkQSPxxqNuEDZgARuv/EXdZcafx/NACDL+DMDcrBeiVhsUn278GeO" Jul 20 21:56:58 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:56:58 minidsp-shd go-librespot[30043]: time="2024-07-20T21:56:58+01:00" level=debug msg="new websocket client" Jul 20 21:56:58 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket established Jul 20 21:56:58 minidsp-shd go-librespot[30043]: time="2024-07-20T21:56:58+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 20 21:56:58 minidsp-shd go-librespot[30043]: time="2024-07-20T21:56:58+01:00" level=debug msg="completed keyexchange" Jul 20 21:56:58 minidsp-shd go-librespot[30043]: time="2024-07-20T21:56:58+01:00" level=debug msg="completed challenge" Jul 20 21:56:58 minidsp-shd go-librespot[30043]: time="2024-07-20T21:56:58+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:56:58 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:56:58 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:56:58 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket closed Jul 20 21:57:01 minidsp-shd volumio[712]: info: Getting Spotify volume Jul 20 21:57:01 minidsp-shd volumio[712]: (node:712) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:57:01 minidsp-shd volumio[712]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 20 21:57:01 minidsp-shd volumio[712]: (node:712) 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: 494) Jul 20 21:57:01 minidsp-shd volumio[712]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Jul 20 21:57:01 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetState Jul 20 21:57:01 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:57:01 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:57:01 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:57:01 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:57:01 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:57:01 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:57:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:57:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1481. Jul 20 21:57:02 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:57:02 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:57:02 minidsp-shd go-librespot[30053]: Librespot-go daemon starting... Jul 20 21:57:02 minidsp-shd go-librespot[30053]: time="2024-07-20T21:57:02+01:00" level=info msg="generated new device id: 3c28fdad3549c5692615273d45c7cfec747a5ced" Jul 20 21:57:02 minidsp-shd go-librespot[30053]: time="2024-07-20T21:57:02+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:57:02 minidsp-shd go-librespot[30053]: time="2024-07-20T21:57:02+01:00" level=debug msg="obtained new client token: AADQbJ7RbWge4knmEtRqpCZ/dVG72B1vDIQ50BIn2neqGOIK6LxadaGyxkh/1ZRTavKaKrOWnBksTs/n8k7paAMukPO58ocjgiUM/+uf6ryS/G5PsAL0XHvYhV2Q2D1Kc2Z3GlKSeggAmuTW4HkzcAIGA1uuc3atUTPCoZRHmpcZwLNUCSgH9Xa0jkJaFmZrmk3Pv4sipjhQft0ALgOSZ8I4PnmeVZFamij9Xhek47RjsDZfk30Tlcs6LoTnyGY=" Jul 20 21:57:02 minidsp-shd go-librespot[30053]: time="2024-07-20T21:57:02+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:57:02 minidsp-shd go-librespot[30053]: time="2024-07-20T21:57:02+01:00" level=debug msg="completed keyexchange" Jul 20 21:57:03 minidsp-shd go-librespot[30053]: time="2024-07-20T21:57:03+01:00" level=debug msg="completed challenge" Jul 20 21:57:03 minidsp-shd go-librespot[30053]: time="2024-07-20T21:57:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:57:03 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:57:03 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:57:04 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:57:04 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:57:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:57:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1482. Jul 20 21:57:06 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:57:06 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:57:06 minidsp-shd go-librespot[30062]: Librespot-go daemon starting... Jul 20 21:57:06 minidsp-shd go-librespot[30062]: time="2024-07-20T21:57:06+01:00" level=info msg="generated new device id: dc2fadd98d16716111eddf0bebe179811558d809" Jul 20 21:57:06 minidsp-shd go-librespot[30062]: time="2024-07-20T21:57:06+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:57:06 minidsp-shd go-librespot[30062]: time="2024-07-20T21:57:06+01:00" level=debug msg="obtained new client token: AADjEzsQMMXUFuXGjx/XIjR4t/WqzY+DFWgpBDQ5pf9hmbX6DAI6WUCPb31ASHzmrpAZkUuA+6+0JOTU/xh3WPfAkvrsNPbEK/IkPOm1gkPjNlUgbg8HNfAQvBxW/8ke6FvXpACVHTp5krk6shdo9qYhByue7irV62nB8RQ320BLMrGGK2iREkHcbQRfu5duT4nezk7Qtv/d9ri73KZCkeaCP/gueQLooO6j6YYGegypX5ugQ+AVabSAYqvUO7M=" Jul 20 21:57:06 minidsp-shd go-librespot[30062]: time="2024-07-20T21:57:06+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:57:06 minidsp-shd go-librespot[30062]: time="2024-07-20T21:57:06+01:00" level=debug msg="completed keyexchange" Jul 20 21:57:07 minidsp-shd go-librespot[30062]: time="2024-07-20T21:57:07+01:00" level=debug msg="completed challenge" Jul 20 21:57:07 minidsp-shd go-librespot[30062]: time="2024-07-20T21:57:07+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:57:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:57:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:57:07 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:57:07 minidsp-shd volumio[712]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:57:08 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 20 21:57:08 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 20 21:57:08 minidsp-shd volumio[712]: info: Discovery: Getting this device information Jul 20 21:57:08 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetState Jul 20 21:57:08 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 20 21:57:09 minidsp-shd volumio[712]: verbose: New Socket.io Connection to 192.168.1.210 from 192.168.1.94 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Total Clients: 8 Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetVisibleSources Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetState Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetQueue Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreStateMachine::getQueue Jul 20 21:57:09 minidsp-shd volumio[712]: info: CorePlayQueue::getQueue Jul 20 21:57:09 minidsp-shd volumio[712]: info: Listing playlists Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 20 21:57:09 minidsp-shd volumio[712]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Jul 20 21:57:09 minidsp-shd volumio[712]: info: Received Get System Info Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 20 21:57:09 minidsp-shd volumio[712]: info: Discovery: Getting this device information Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetState Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetState Jul 20 21:57:09 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jul 20 21:57:10 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:57:10 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1483. Jul 20 21:57:10 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:57:10 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:57:10 minidsp-shd go-librespot[30070]: Librespot-go daemon starting... Jul 20 21:57:10 minidsp-shd go-librespot[30070]: time="2024-07-20T21:57:10+01:00" level=info msg="generated new device id: c8200c0fcbc41563d517365d2974b949f356255d" Jul 20 21:57:10 minidsp-shd go-librespot[30070]: time="2024-07-20T21:57:10+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:57:10 minidsp-shd go-librespot[30070]: time="2024-07-20T21:57:10+01:00" level=debug msg="obtained new client token: AAAwNb8xuRDMHVdwfUo758hQMu0rL8kB3o4/27QndrVqhN07oE73GnVSxBkdXUTCCuD3d11rddrCi3+eM0rV4tDMlUpcSAlTYRFG1Mbnpe1z4VzrpZk0KDacTD8iVp8z99bVcHRj/7uYr8l/QHlEn4HWNWp86ebllOqtHQWfMcAjMmjzFPRu+AhaUFI2A5UsSVe12Q7URfjaySfdD9oXcEnAjBVLqRQ4rrN/lgOhqcOlKfVOtEIpVUU1Zjf7Nos=" Jul 20 21:57:10 minidsp-shd volumio[712]: info: Initializing connection to go-librespot Websocket Jul 20 21:57:10 minidsp-shd go-librespot[30070]: time="2024-07-20T21:57:10+01:00" level=debug msg="new websocket client" Jul 20 21:57:10 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket established Jul 20 21:57:10 minidsp-shd go-librespot[30070]: time="2024-07-20T21:57:10+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:57:11 minidsp-shd go-librespot[30070]: time="2024-07-20T21:57:11+01:00" level=debug msg="completed keyexchange" Jul 20 21:57:11 minidsp-shd go-librespot[30070]: time="2024-07-20T21:57:11+01:00" level=debug msg="completed challenge" Jul 20 21:57:11 minidsp-shd go-librespot[30070]: time="2024-07-20T21:57:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 20 21:57:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 20 21:57:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 20 21:57:11 minidsp-shd volumio[712]: info: Connection to go-librespot Websocket closed Jul 20 21:57:13 minidsp-shd volumio[712]: info: Getting Spotify volume Jul 20 21:57:13 minidsp-shd volumio[712]: (node:712) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 20 21:57:13 minidsp-shd volumio[712]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 20 21:57:13 minidsp-shd volumio[712]: (node:712) 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: 495) Jul 20 21:57:13 minidsp-shd volumio[712]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Jul 20 21:57:13 minidsp-shd volumio[712]: info: CoreCommandRouter::volumioGetState Jul 20 21:57:13 minidsp-shd volumio[712]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Jul 20 21:57:13 minidsp-shd volumio[712]: SPOTIFY: SPOTIFY VOLUME 93 Jul 20 21:57:13 minidsp-shd volumio[712]: SPOTIFY: VOLUMIO VOLUME 92 Jul 20 21:57:13 minidsp-shd volumio[712]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 20 21:57:14 minidsp-shd volumio[712]: Searching all installed plugins Jul 20 21:57:14 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 20 21:57:14 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: , search Jul 20 21:57:14 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jul 20 21:57:14 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Jul 20 21:57:14 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Jul 20 21:57:14 minidsp-shd volumio[712]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Jul 20 21:57:14 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: webradio , search Jul 20 21:57:14 minidsp-shd volumio[712]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Jul 20 21:57:14 minidsp-shd volumio[712]: info: [1721509034391] ControllerCalmRadio::searchCategories Jul 20 21:57:14 minidsp-shd volumio[712]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 20 21:57:14 minidsp-shd volumio[712]: TypeError: Cannot read property 'cats' of undefined Jul 20 21:57:14 minidsp-shd volumio[712]: at ControllerCalmRadio.searchCategories (/data/plugins/music_service/calmradio/index.js:615:42) Jul 20 21:57:14 minidsp-shd volumio[712]: at ControllerCalmRadio.search (/data/plugins/music_service/calmradio/index.js:665:28) Jul 20 21:57:14 minidsp-shd volumio[712]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1077:32) Jul 20 21:57:14 minidsp-shd volumio[712]: at CoreMusicLibrary.searchOnPlugin (/volumio/app/musiclibrary.js:668:44) Jul 20 21:57:14 minidsp-shd volumio[712]: at CoreMusicLibrary.search (/volumio/app/musiclibrary.js:455:27) Jul 20 21:57:14 minidsp-shd volumio[712]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:457:44) Jul 20 21:57:14 minidsp-shd volumio[712]: at Socket.emit (events.js:400:28) Jul 20 21:57:14 minidsp-shd volumio[712]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Jul 20 21:57:14 minidsp-shd volumio[712]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Jul 20 21:57:14 minidsp-shd volumio[712]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 20 21:57:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 20 21:57:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1484. Jul 20 21:57:14 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Jul 20 21:57:14 minidsp-shd systemd[1]: Started go-librespot Daemon. Jul 20 21:57:14 minidsp-shd go-librespot[30086]: Librespot-go daemon starting... Jul 20 21:57:14 minidsp-shd go-librespot[30086]: time="2024-07-20T21:57:14+01:00" level=info msg="generated new device id: 1c7a4d61b152456583db12ab526e35ae66f4ff49" Jul 20 21:57:14 minidsp-shd go-librespot[30086]: time="2024-07-20T21:57:14+01:00" level=debug msg="stored credentials found for lbhj574own4f1tcjm2qey9a4g" Jul 20 21:57:15 minidsp-shd go-librespot[30086]: time="2024-07-20T21:57:15+01:00" level=debug msg="obtained new client token: AABOkF8qK7YfXEONZgOVztC5WeAhWa9jF6Z2+QwjQqe2aI3WDroeCGbI1oTob6bi0L/BFTI1juQSD0euZcloKrorekhNMtTofhNa3vFs87B4Av1efS3HA9VnDFmsLSPgutvpNAdL74ZkPMNiWnJKFrGGAtY4zKmU0Sg8jdlGxVRWsvIV6Fp8oxGpmjEwVq8+QLsd1brp3/p4R0P87oIQO0nkO+vmjZfLJHSxgYxHnzA/Dvw38MSYnRhmGxqJ" Jul 20 21:57:15 minidsp-shd go-librespot[30086]: time="2024-07-20T21:57:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 20 21:57:15 minidsp-shd sudo[30095]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-20 21:56 Jul 20 21:57:15 minidsp-shd sudo[30095]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="17fcb754ddd6bd152b01008c46cc4ba1ca48bf35" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="281cefcd7a302aa7cfba569185cf7aae19b8c376" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="minidspshd" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 22 Mar 2024 03:00:28 PM CET" VOLUMIO_VERSION="3.608" VOLUMIO_HARDWARE="nanopineo2" VOLUMIO_DEVICENAME="NanoPi Neo2" VOLUMIO_VENDOR="miniDSP" VOLUMIO_MODEL="SHD" VOLUMIO_VENDOR_MODEL="miniDSP SHD" VOLUMIO_HASH="29ccfe8a9cff19911db4b736879ac117"