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