-- Logs begin at Thu 2019-02-14 10:11:59 GMT, end at Fri 2025-05-23 12:55:51 BST. -- May 23 12:54:01 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:01 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 192. May 23 12:54:02 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:02 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:02 volumio go-librespot[5418]: Librespot-go daemon starting... May 23 12:54:02 volumio go-librespot[5418]: time="2025-05-23T12:54:02+01:00" level=info msg="generated new device id: 5828ecb34cde3c58f62f35fd5d725f8154cc9d1a" May 23 12:54:02 volumio go-librespot[5418]: time="2025-05-23T12:54:02+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:02 volumio go-librespot[5418]: time="2025-05-23T12:54:02+01:00" level=debug msg="obtained new client token: AAAw0mUJlia5WGUs5ZEp/+r3iEpfE3IFb8owFNL9aTFOC3i+FP6xvYFH75Nw6nnGA9M2ULORsS2hJ94TJ0l14VAQ5yNcOWQwxWIWTABXYHqV+XC3tn6crwq3QMJRME7+hTIP2bAQBaMkMhWCEr72BW9db26pNpZ2rIw/LvytjFh7DIPEOaGYzmferRhlDe195xG4AksnZQXuOjVggEQg8ngDUQ7qXzRdbl5qf311X4AFagjfhPHMr8z94PbR" May 23 12:54:03 volumio go-librespot[5418]: time="2025-05-23T12:54:03+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]" May 23 12:54:03 volumio go-librespot[5418]: time="2025-05-23T12:54:03+01:00" level=debug msg="completed keyexchange" May 23 12:54:03 volumio go-librespot[5418]: time="2025-05-23T12:54:03+01:00" level=debug msg="completed challenge" May 23 12:54:03 volumio go-librespot[5418]: time="2025-05-23T12:54: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" May 23 12:54:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:04 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:04 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 193. May 23 12:54:06 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:06 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:06 volumio go-librespot[5478]: Librespot-go daemon starting... May 23 12:54:06 volumio go-librespot[5478]: time="2025-05-23T12:54:06+01:00" level=info msg="generated new device id: 439900c7459b79905d5d82ad1fadd75d42f08a47" May 23 12:54:06 volumio go-librespot[5478]: time="2025-05-23T12:54:06+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:07 volumio go-librespot[5478]: time="2025-05-23T12:54:07+01:00" level=debug msg="obtained new client token: AADut+NmVSxN8Q6Hl8cGpA6CWFoZlp1YgTURI/yXBa0gFQgYj2wwjn+bCx/UBV0MNg+GO/ZOxKIQVbo10dJQmJZlmMqeTtAbl1q102lV+IsKaqupwBz8uHxnEllOHQfZm0EoIaMmKc2TEdJBJ/kAfudWCoDRj+DsTTaw8JqLGAcq5Bg5QwxvbThmIVfv0iqQxMzjJco3K3oAlg8PASkjIpHVkEHu+wb9xialF+KiziivNhZRUGSHFvBHEA==" May 23 12:54:07 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:07 volumio go-librespot[5478]: time="2025-05-23T12:54:07+01:00" level=debug msg="new websocket client" May 23 12:54:07 volumio volumio[982]: info: Connection to go-librespot Websocket established May 23 12:54:07 volumio go-librespot[5478]: time="2025-05-23T12:54: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-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 23 12:54:07 volumio go-librespot[5478]: time="2025-05-23T12:54:07+01:00" level=debug msg="completed keyexchange" May 23 12:54:08 volumio go-librespot[5478]: time="2025-05-23T12:54:08+01:00" level=debug msg="completed challenge" May 23 12:54:08 volumio go-librespot[5478]: time="2025-05-23T12:54:08+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:54:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:08 volumio volumio[982]: info: Connection to go-librespot Websocket closed May 23 12:54:10 volumio volumio[982]: info: Getting Spotify volume May 23 12:54:10 volumio volumio[982]: (node:982) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:10 volumio volumio[982]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 23 12:54:10 volumio volumio[982]: (node:982) 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: 67) May 23 12:54:10 volumio volumio[982]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 23 12:54:10 volumio volumio[982]: info: CoreCommandRouter::volumioGetState May 23 12:54:10 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:54:10 volumio volumio[982]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 23 12:54:11 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:11 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 194. May 23 12:54:11 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:11 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:11 volumio go-librespot[5489]: Librespot-go daemon starting... May 23 12:54:11 volumio go-librespot[5489]: time="2025-05-23T12:54:11+01:00" level=info msg="generated new device id: 73509331256d5c35b88ccce70c39e9aadd27df03" May 23 12:54:11 volumio go-librespot[5489]: time="2025-05-23T12:54:11+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:11 volumio go-librespot[5489]: time="2025-05-23T12:54:11+01:00" level=debug msg="obtained new client token: AADaklggDtYt4LekqzzHUPwSSYQsImyyQWBLzEBXl1CnIuvmX6Bp8MjsZj9Zmxr788RllpDoou3TVGlRxLXkYrB3m0DanLkrplwJ9bkbArDZcpSynCWw0TTrs21EJvzLAkUZZPBaevxBUzVGvHgbkspQp3HK8pXRy5nUQ3+QbA3sUkFqL3hTrZ/NxBI+bxpZlaXdeCBt3EqYoAEdV0qffhaqhiaE1HcZaVZWRNy4FI9cJwq9Pc2WaNX/KbJK" May 23 12:54:11 volumio go-librespot[5489]: time="2025-05-23T12:54: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-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 23 12:54:11 volumio go-librespot[5489]: time="2025-05-23T12:54:11+01:00" level=debug msg="completed keyexchange" May 23 12:54:12 volumio go-librespot[5489]: time="2025-05-23T12:54:12+01:00" level=debug msg="completed challenge" May 23 12:54:12 volumio go-librespot[5489]: time="2025-05-23T12:54: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" May 23 12:54:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:14 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:14 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 195. May 23 12:54:15 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:15 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:15 volumio go-librespot[5512]: Librespot-go daemon starting... May 23 12:54:15 volumio go-librespot[5512]: time="2025-05-23T12:54:15+01:00" level=info msg="generated new device id: 20f7f870bc2c0ecab6363ebb86a87bf04f7f6208" May 23 12:54:15 volumio go-librespot[5512]: time="2025-05-23T12:54:15+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:15 volumio go-librespot[5512]: time="2025-05-23T12:54:15+01:00" level=debug msg="obtained new client token: AADz55DEaFOXLESb4dkkX0wDGChQRrdDI0j0a65o4WSVMmMTWb/QslUyHRTJC6QbKRk638onFbpc3SgQC3HBvFyCtyK+Z8Sn/KUJPBRVrwLnnaH26FBv5MAzaU4NIMtpqt1Td/PpNAoiBrjw7flMAlyaY2mfQjyO3QI93QnQs0MbrX75al9R89KXFB796qWFyEF9DQFWcLMt52eOZK80AS/XdvZeUN2mbaPoQyWNlq6f4R/+sSEI3NdJav+y" May 23 12:54:15 volumio go-librespot[5512]: time="2025-05-23T12:54: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-gew4.spotify.com:80]" May 23 12:54:16 volumio go-librespot[5512]: time="2025-05-23T12:54:16+01:00" level=debug msg="completed keyexchange" May 23 12:54:16 volumio go-librespot[5512]: time="2025-05-23T12:54:16+01:00" level=debug msg="completed challenge" May 23 12:54:16 volumio go-librespot[5512]: time="2025-05-23T12:54: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" May 23 12:54:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:17 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:17 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 196. May 23 12:54:19 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:19 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:19 volumio go-librespot[5520]: Librespot-go daemon starting... May 23 12:54:19 volumio go-librespot[5520]: time="2025-05-23T12:54:19+01:00" level=info msg="generated new device id: 837596d1e8e9e486f0fa1099740370e72a9298b7" May 23 12:54:19 volumio go-librespot[5520]: time="2025-05-23T12:54:19+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:19 volumio go-librespot[5520]: time="2025-05-23T12:54:19+01:00" level=debug msg="obtained new client token: AADnpWFWyhbKBJjzmfOQUjIZ+FkDhADnhaAJcJlMx3Zfh8+ExDv/AzDXEKEnsmguB+4My1q0qKyZLp9677GrpGjqwbsuakXinjjGjlJwQ6EaQMmIPofoiK1XRqYUapqkYmLIX9IkFrb1ToE6vOZTfKg1c8KaAm4FXkVHRRdrn7dQ6hyerxcxZhjXPERWulo/o5BgSq3hJmpNllYG3GA1L3uHZsbQj4EgKeGohJtZ0G0hVYF7xyWZdZsSgnlf" May 23 12:54:20 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:20 volumio go-librespot[5520]: time="2025-05-23T12:54:20+01:00" level=debug msg="new websocket client" May 23 12:54:20 volumio volumio[982]: info: Connection to go-librespot Websocket established May 23 12:54:20 volumio go-librespot[5520]: time="2025-05-23T12:54:20+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]" May 23 12:54:20 volumio go-librespot[5520]: time="2025-05-23T12:54:20+01:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.65.9:4070: connect: connection refused" May 23 12:54:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:20 volumio volumio[982]: info: Connection to go-librespot Websocket closed May 23 12:54:23 volumio volumio[982]: info: Getting Spotify volume May 23 12:54:23 volumio volumio[982]: (node:982) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:23 volumio volumio[982]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 23 12:54:23 volumio volumio[982]: (node:982) 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: 68) May 23 12:54:23 volumio volumio[982]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 23 12:54:23 volumio volumio[982]: info: CoreCommandRouter::volumioGetState May 23 12:54:23 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:54:23 volumio volumio[982]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 23 12:54:23 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:23 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 197. May 23 12:54:23 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:23 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:23 volumio go-librespot[5528]: Librespot-go daemon starting... May 23 12:54:23 volumio go-librespot[5528]: time="2025-05-23T12:54:23+01:00" level=info msg="generated new device id: 3f3e687a3c135b62903b7ec7e9ebe0ea60f7e59d" May 23 12:54:23 volumio go-librespot[5528]: time="2025-05-23T12:54:23+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:23 volumio go-librespot[5528]: time="2025-05-23T12:54:23+01:00" level=debug msg="obtained new client token: AACEZfSSO3d8qXIaCu7iO/OmPRtDjUBYUuUpb6H+pGZaOLORUCP1Lq7P2x66tAQ05DUswHxZpX+ubKOsMdk+vML4kcT8iZxDlr1MQWmQgIFK6wxbY4DV6ykmPXuTj3wLRfcsyCjLaLXXhFv+sfaR7B/5eHrIEc2hsLCXNYfPjevKPJ+XAHwL1t1Y3Fm6z8JR2NCGCU4q9mVZUT8wzQeh7Wj60DXOxWLw+uw/z9rRQs9GQHdhqs0QLM/8SUJa" May 23 12:54:23 volumio go-librespot[5528]: time="2025-05-23T12:54:23+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]" May 23 12:54:24 volumio go-librespot[5528]: time="2025-05-23T12:54:24+01:00" level=debug msg="completed keyexchange" May 23 12:54:24 volumio go-librespot[5528]: time="2025-05-23T12:54:24+01:00" level=debug msg="completed challenge" May 23 12:54:24 volumio go-librespot[5528]: time="2025-05-23T12:54: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" May 23 12:54:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:26 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:26 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 198. May 23 12:54:27 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:27 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:27 volumio go-librespot[5550]: Librespot-go daemon starting... May 23 12:54:27 volumio go-librespot[5550]: time="2025-05-23T12:54:27+01:00" level=info msg="generated new device id: 9a7b245ff6eebd09d5352103eeda42b3655c83b5" May 23 12:54:27 volumio go-librespot[5550]: time="2025-05-23T12:54:27+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:27 volumio go-librespot[5550]: time="2025-05-23T12:54:27+01:00" level=debug msg="obtained new client token: AAClqMg01DFPOcLfIhOy9vW0sXle0xWGQXKBw/YzXHvWUtcOZZKgb1OaHGC/Fu3jeM4xIADt1D+yDIoABI2ikIPWqpTeeVu0atg+mhX43vzRZXVe3lsMYVhi1OMJFPoJj7nARS2x1xHXLgiLeVy2EvM2e9QyMWP3RjRDyXl+/scLB2To+8KjoXaXwTHlNx/g2VyAR1ZvtJ3RhXOJgTcuiw4auq+c3L35h0lTwfDIFpeQnNfHcWqBgfwaFhB1" May 23 12:54:28 volumio go-librespot[5550]: time="2025-05-23T12:54: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-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 23 12:54:28 volumio go-librespot[5550]: time="2025-05-23T12:54:28+01:00" level=debug msg="completed keyexchange" May 23 12:54:28 volumio go-librespot[5550]: time="2025-05-23T12:54:28+01:00" level=debug msg="completed challenge" May 23 12:54:28 volumio go-librespot[5550]: time="2025-05-23T12:54:28+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:54:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:29 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:29 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:31 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 199. May 23 12:54:31 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:31 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:31 volumio go-librespot[5562]: Librespot-go daemon starting... May 23 12:54:31 volumio go-librespot[5562]: time="2025-05-23T12:54:31+01:00" level=info msg="generated new device id: c2f61ac10cd6613ebaa433b40742a5044dca0676" May 23 12:54:31 volumio go-librespot[5562]: time="2025-05-23T12:54:31+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:32 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:32 volumio go-librespot[5562]: time="2025-05-23T12:54:32+01:00" level=debug msg="new websocket client" May 23 12:54:32 volumio volumio[982]: info: Connection to go-librespot Websocket established May 23 12:54:32 volumio go-librespot[5562]: time="2025-05-23T12:54:32+01:00" level=debug msg="obtained new client token: AACXrXe1jzgaOjtD+mOZBsUyVCiwfLRj5z0R2DC3o+BArtidJjQPLRL8S5PROfpwvHG4WoQwKAtDBCZrnPB2Ad5Py0JCchuxmrq7nUmuwbVSOBke9rloFBY01deSLg33f5UhWobF3S+hGNH8tdw8eMgUPJxnEY/gHCOExKeosGqNBauHaE0W+3QraVu5UNCuDCYjeDikYIoxOCCTiWmRYSFB69BuEwOvyV1muPZshYZDJ8On8ccdZyExiQ==" May 23 12:54:32 volumio go-librespot[5562]: time="2025-05-23T12:54: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" May 23 12:54:32 volumio go-librespot[5562]: time="2025-05-23T12:54:32+01:00" level=debug msg="completed keyexchange" May 23 12:54:33 volumio go-librespot[5562]: time="2025-05-23T12:54:33+01:00" level=debug msg="completed challenge" May 23 12:54:33 volumio go-librespot[5562]: time="2025-05-23T12:54: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" May 23 12:54:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:33 volumio volumio[982]: info: Connection to go-librespot Websocket closed May 23 12:54:35 volumio volumio[982]: info: Getting Spotify volume May 23 12:54:35 volumio volumio[982]: (node:982) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:35 volumio volumio[982]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 23 12:54:35 volumio volumio[982]: (node:982) 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: 69) May 23 12:54:35 volumio volumio[982]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 23 12:54:35 volumio volumio[982]: info: CoreCommandRouter::volumioGetState May 23 12:54:35 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:54:35 volumio volumio[982]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 23 12:54:36 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:36 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 200. May 23 12:54:36 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:36 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:36 volumio go-librespot[5584]: Librespot-go daemon starting... May 23 12:54:36 volumio go-librespot[5584]: time="2025-05-23T12:54:36+01:00" level=info msg="generated new device id: 56accf0ce2be82b4f58b3ca984534d50d9966655" May 23 12:54:36 volumio go-librespot[5584]: time="2025-05-23T12:54:36+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:36 volumio go-librespot[5584]: time="2025-05-23T12:54:36+01:00" level=debug msg="obtained new client token: AACNyVkD1R3m24UpdA0N4F72TkbbsAlysQJSdUueeH6RMAfWuv5GHDAAX0GhLAT2umhSQ7goiKOV1uKl4adFABlHet96bRYioqbXPv7j6jTxsSz504QY9gvHnv62hy7/eFnWel5Q5AYKrg/yU2KHKWdHyqSqZG4NXs2I3qxPBnXyH8GQ7Ui5KrfAs6FgO0EKQwksB0SitOJCwAyIlLBg5IkHNB7uLXAPe9vasWkHxMzVDjC4QNL71A/B68XI" May 23 12:54:36 volumio go-librespot[5584]: time="2025-05-23T12:54: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" May 23 12:54:36 volumio go-librespot[5584]: time="2025-05-23T12:54:36+01:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.65.9:4070: connect: connection refused" May 23 12:54:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:39 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:39 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 201. May 23 12:54:39 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:39 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:39 volumio go-librespot[5592]: Librespot-go daemon starting... May 23 12:54:39 volumio go-librespot[5592]: time="2025-05-23T12:54:39+01:00" level=info msg="generated new device id: daa47a948089a24e47839eb594b8e20d7027bfa0" May 23 12:54:39 volumio go-librespot[5592]: time="2025-05-23T12:54:39+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:40 volumio go-librespot[5592]: time="2025-05-23T12:54:40+01:00" level=debug msg="obtained new client token: AADcPT+D6NfQuvGPR0jCsbmjPUxCzcHriFpfw1csa1LZP0jhdTXKW7QnbZjUuCH0aIccVcbLaUBNbJ1DmjOhny8gyKxaUT/LKtrrj7J3eCHl03hsiAG9c2G5q3GOAKVCpfni0JetYcfcOuD+T27KwNCX5YhrgMucJsNTAEHKvos/DBfk3QJkNCimsXIXfdtZj7rYzeFc1tIisRyl1Bqf2Fj9tWgB14FSFPyBxg46aJ5WDiHjoaAHed/3Eg==" May 23 12:54:40 volumio go-librespot[5592]: time="2025-05-23T12:54:40+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]" May 23 12:54:40 volumio go-librespot[5592]: time="2025-05-23T12:54:40+01:00" level=debug msg="completed keyexchange" May 23 12:54:41 volumio go-librespot[5592]: time="2025-05-23T12:54:41+01:00" level=debug msg="completed challenge" May 23 12:54:41 volumio go-librespot[5592]: time="2025-05-23T12:54: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" May 23 12:54:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:42 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:42 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:44 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 202. May 23 12:54:44 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:44 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:44 volumio go-librespot[5614]: Librespot-go daemon starting... May 23 12:54:44 volumio go-librespot[5614]: time="2025-05-23T12:54:44+01:00" level=info msg="generated new device id: 940956f6a3ea3d216699235172fb9b23ebc4ab0e" May 23 12:54:44 volumio go-librespot[5614]: time="2025-05-23T12:54:44+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:44 volumio go-librespot[5614]: time="2025-05-23T12:54:44+01:00" level=debug msg="obtained new client token: AAB+Mut768BSjf4eucVTZ8PNWaT8JqNy6neVcmDVaYO/wGhOdfoDfL3HOYijm2ulLIvVgTzVn6tebvmGhCxHTgBGRZ/SS2KHMsAAw5+2kdt0HlwYN7Otdty10jBAzwoGeVkE/EVReRmwJopSFMZoL9QqaP+0LJCXD4LYJxb6rGN+wSZz06KjC6rcJgeCjATcjC9m1OPIRtiXRP9W2x/eBmmaHaEn8oVRutwbnsP6y1Mk/cZ+xEjKfXjQjyNs" May 23 12:54:44 volumio go-librespot[5614]: time="2025-05-23T12:54:44+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]" May 23 12:54:44 volumio go-librespot[5614]: time="2025-05-23T12:54:44+01:00" level=debug msg="completed keyexchange" May 23 12:54:45 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:45 volumio go-librespot[5614]: time="2025-05-23T12:54:45+01:00" level=debug msg="new websocket client" May 23 12:54:45 volumio volumio[982]: info: Connection to go-librespot Websocket established May 23 12:54:45 volumio go-librespot[5614]: time="2025-05-23T12:54:45+01:00" level=debug msg="completed challenge" May 23 12:54:45 volumio go-librespot[5614]: time="2025-05-23T12:54:45+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:54:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:45 volumio volumio[982]: info: Connection to go-librespot Websocket closed May 23 12:54:48 volumio volumio[982]: info: Getting Spotify volume May 23 12:54:48 volumio volumio[982]: (node:982) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:48 volumio volumio[982]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 23 12:54:48 volumio volumio[982]: (node:982) 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: 70) May 23 12:54:48 volumio volumio[982]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 23 12:54:48 volumio volumio[982]: info: CoreCommandRouter::volumioGetState May 23 12:54:48 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:54:48 volumio volumio[982]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 23 12:54:48 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:48 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:48 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 203. May 23 12:54:48 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:48 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:48 volumio go-librespot[5622]: Librespot-go daemon starting... May 23 12:54:48 volumio go-librespot[5622]: time="2025-05-23T12:54:48+01:00" level=info msg="generated new device id: 33147c5990bed56b9ccd9bf87643ef451bdeebed" May 23 12:54:48 volumio go-librespot[5622]: time="2025-05-23T12:54:48+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:48 volumio go-librespot[5622]: time="2025-05-23T12:54:48+01:00" level=debug msg="obtained new client token: AADSdVNGMYQtrjFQn+o/jtTgGC8AZ7FcxTASCKp+2pqHUUMX4OWyFyQgO8KQHaGR2hWiIZmRHdVtKB/xOZCreEdGQ/g6RbBe0ZHALHmvwBNHMl/O+2Be3XNGvJIe63obxipBfnc3io7tmvE9QBO0pxMo4u7ReoTCKcQgGxFAvL5dkE3WAcJV8i36pReHjjBk/K5FyO3p22LyDwSg+TaNKdv+L221LTLvLDPmWshUEHfibwJNJXei+bdcJAiZ" May 23 12:54:48 volumio go-librespot[5622]: time="2025-05-23T12:54:48+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]" May 23 12:54:48 volumio go-librespot[5622]: time="2025-05-23T12:54:48+01:00" level=debug msg="completed keyexchange" May 23 12:54:49 volumio go-librespot[5622]: time="2025-05-23T12:54:49+01:00" level=debug msg="completed challenge" May 23 12:54:49 volumio go-librespot[5622]: time="2025-05-23T12:54:49+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:54:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:51 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:51 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:52 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 204. May 23 12:54:52 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:52 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:52 volumio go-librespot[5634]: Librespot-go daemon starting... May 23 12:54:52 volumio go-librespot[5634]: time="2025-05-23T12:54:52+01:00" level=info msg="generated new device id: 8119aa3f2fae5bb3062a2b8eb090fad67e8de9c5" May 23 12:54:52 volumio go-librespot[5634]: time="2025-05-23T12:54:52+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:53 volumio go-librespot[5634]: time="2025-05-23T12:54:53+01:00" level=debug msg="obtained new client token: AADSr19TTvFfpo9rHzgQapl2BVC+wMIitTkTMu/R7PZnEE/BhVi1drhLioHkHcn1crOkmWGGClxRJ/sOaMNxzZ+ipRCi7blFPhAdCv38CqaoYbMSxKAZt4O64I70HDS58hz7zCSHxelKrzMg954R//CPEexHekBwBg8FnMt7o76Yuq4kSlMbTklM97xZlJlFKLkr97pOKsqPZE1aYZhicLGOky2EFiEGxBR7a5gSOSZtGtAKlQ93g0VIA+JK" May 23 12:54:53 volumio go-librespot[5634]: time="2025-05-23T12:54: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" May 23 12:54:53 volumio go-librespot[5634]: time="2025-05-23T12:54:53+01:00" level=debug msg="completed keyexchange" May 23 12:54:53 volumio go-librespot[5634]: time="2025-05-23T12:54:53+01:00" level=debug msg="completed challenge" May 23 12:54:53 volumio go-librespot[5634]: time="2025-05-23T12:54:53+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:54:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:54 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:54 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:54:56 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:54:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 205. May 23 12:54:56 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:54:56 volumio systemd[1]: Started go-librespot Daemon. May 23 12:54:56 volumio go-librespot[5657]: Librespot-go daemon starting... May 23 12:54:56 volumio go-librespot[5657]: time="2025-05-23T12:54:56+01:00" level=info msg="generated new device id: 76549c83db89fcc54fb38efa7ccc04c6b210c85b" May 23 12:54:56 volumio go-librespot[5657]: time="2025-05-23T12:54:56+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:54:57 volumio go-librespot[5657]: time="2025-05-23T12:54:57+01:00" level=debug msg="obtained new client token: AADpVeyIkaBUHkGYE4lwLRMEVbdC8T8eJ6aVebgxk3+I3rikekchNG7MpU+QIjswC0J/OEwrvBo+k6gIbGSkUbG5dK9m3hXJg/xHyQWFdLDluY+1PEHNiVgiF7JEBSX5riUSdLaHCiTYRRGIQ2iO0k8JFfNrH/NE4zB++3QtK70O0FLxD9qU0j1fnnGhT1tZQBhnOCniq0kCYtWwuMSupK5rHbhNxMLRMAi9dVjb+9x97YpOzlHLdnNQzA==" May 23 12:54:57 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:54:57 volumio go-librespot[5657]: time="2025-05-23T12:54:57+01:00" level=debug msg="new websocket client" May 23 12:54:57 volumio volumio[982]: info: Connection to go-librespot Websocket established May 23 12:54:57 volumio go-librespot[5657]: time="2025-05-23T12:54:57+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]" May 23 12:54:57 volumio go-librespot[5657]: time="2025-05-23T12:54:57+01:00" level=debug msg="completed keyexchange" May 23 12:54:58 volumio go-librespot[5657]: time="2025-05-23T12:54:58+01:00" level=debug msg="completed challenge" May 23 12:54:58 volumio go-librespot[5657]: time="2025-05-23T12:54: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" May 23 12:54:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:54:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:54:58 volumio volumio[982]: info: Connection to go-librespot Websocket closed May 23 12:55:00 volumio volumio[982]: info: Getting Spotify volume May 23 12:55:00 volumio volumio[982]: (node:982) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:00 volumio volumio[982]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 23 12:55:00 volumio volumio[982]: (node:982) 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: 71) May 23 12:55:00 volumio volumio[982]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 23 12:55:00 volumio volumio[982]: info: CoreCommandRouter::volumioGetState May 23 12:55:00 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:00 volumio volumio[982]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 23 12:55:01 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:01 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 206. May 23 12:55:01 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:01 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:01 volumio go-librespot[5666]: Librespot-go daemon starting... May 23 12:55:01 volumio go-librespot[5666]: time="2025-05-23T12:55:01+01:00" level=info msg="generated new device id: cfd18514f1f4f9f613cea5ab161eef659149d553" May 23 12:55:01 volumio go-librespot[5666]: time="2025-05-23T12:55:01+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:01 volumio go-librespot[5666]: time="2025-05-23T12:55:01+01:00" level=debug msg="obtained new client token: AABjiZshaaSzROT/FES1H9DFzGm+WyMRIHr4TZiVfghV3s72kF2tp+KKQ+pdNXX8Pbu33mvADo3iWcCQF9uQSbo8u9VRvAfAEWi2HskXtYUv1QO8yrw0hWoGePk8qWP8eGjk/6Mna0JeVXCF9MURx2M8bJ4k7/RrhlpbILxab4pVzkZ2o6b0BfFPTQZdtYP7gSzK4B/Xei9NlpuWA4/As9AGGPEuEAcKwwXxkSPj+YHW91h2z1f0MuI6VDsm" May 23 12:55:01 volumio go-librespot[5666]: time="2025-05-23T12:55:01+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]" May 23 12:55:01 volumio go-librespot[5666]: time="2025-05-23T12:55:01+01:00" level=debug msg="completed keyexchange" May 23 12:55:02 volumio go-librespot[5666]: time="2025-05-23T12:55:02+01:00" level=debug msg="completed challenge" May 23 12:55:02 volumio go-librespot[5666]: time="2025-05-23T12:55:02+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:04 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:04 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:05 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 207. May 23 12:55:05 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:05 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:05 volumio go-librespot[5732]: Librespot-go daemon starting... May 23 12:55:05 volumio go-librespot[5732]: time="2025-05-23T12:55:05+01:00" level=info msg="generated new device id: 6f149ddf5cc95319a60214a7793ca47d84c97768" May 23 12:55:05 volumio go-librespot[5732]: time="2025-05-23T12:55:05+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:05 volumio go-librespot[5732]: time="2025-05-23T12:55:05+01:00" level=debug msg="obtained new client token: AACJFmA+8ZkGliSZxM+wqw/2SBAznUrYZ4Xs7OkknSYLfoefFpx01R24kLvXT7n3TASfwfzzcFg9qnrsu35pQqjhPwWlweEdHB8TQr6qFatxYXucIG/mmrKMoaCoCBE8A5MgkgeXVty1L9wQqXUs6Uz6m3nzke6OpFfnsKErqOAqlYHJ8RrCRM+W8cKNOqJs6SJMfaNRuq6NBg9tVdp6tls4GGs0Fxqk2roXir+4EXBkVN0tuI7rhnoXMTGB" May 23 12:55:05 volumio go-librespot[5732]: time="2025-05-23T12:55:05+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]" May 23 12:55:06 volumio go-librespot[5732]: time="2025-05-23T12:55:06+01:00" level=debug msg="completed keyexchange" May 23 12:55:06 volumio go-librespot[5732]: time="2025-05-23T12:55:06+01:00" level=debug msg="completed challenge" May 23 12:55:06 volumio go-librespot[5732]: time="2025-05-23T12:55:06+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:07 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:07 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:09 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 208. May 23 12:55:09 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:09 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:09 volumio go-librespot[5741]: Librespot-go daemon starting... May 23 12:55:09 volumio go-librespot[5741]: time="2025-05-23T12:55:09+01:00" level=info msg="generated new device id: 66647c58dc9d33e043bd8a899b2186ceb9549379" May 23 12:55:09 volumio go-librespot[5741]: time="2025-05-23T12:55:09+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:09 volumio go-librespot[5741]: time="2025-05-23T12:55:09+01:00" level=debug msg="obtained new client token: AADo6Rn9VZOgBSpHk8EhtTbEzPTAWAAj0jKhvuRxv7Y95+bc9aKlD2h/DkGq8qTH2O755kz/HpWQdcPCkBxSl0DuaNDurZ/yFiq3WsqEgEpCjMhHEzwZApIv4y/ABJYUI0RnYhRFI49FBlabSjBZ0W46+A346msrsCBhCnFKD286wGd+0AjP/EdoNCUxAOBFqXClicx5Yk6uOhJ8F0MeHaKGK0R+v/wcEwQvD0RO1TvMNW71XR6tsdmMdDzY" May 23 12:55:10 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:10 volumio go-librespot[5741]: time="2025-05-23T12:55:10+01:00" level=debug msg="new websocket client" May 23 12:55:10 volumio volumio[982]: info: Connection to go-librespot Websocket established May 23 12:55:10 volumio go-librespot[5741]: time="2025-05-23T12:55: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-gew4.spotify.com:80]" May 23 12:55:10 volumio go-librespot[5741]: time="2025-05-23T12:55:10+01:00" level=debug msg="completed keyexchange" May 23 12:55:10 volumio go-librespot[5741]: time="2025-05-23T12:55:10+01:00" level=debug msg="completed challenge" May 23 12:55:10 volumio go-librespot[5741]: time="2025-05-23T12:55:10+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:10 volumio volumio[982]: info: Connection to go-librespot Websocket closed May 23 12:55:13 volumio volumio[982]: info: Getting Spotify volume May 23 12:55:13 volumio volumio[982]: (node:982) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:13 volumio volumio[982]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 23 12:55:13 volumio volumio[982]: (node:982) 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: 72) May 23 12:55:13 volumio volumio[982]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 23 12:55:13 volumio volumio[982]: info: CoreCommandRouter::volumioGetState May 23 12:55:13 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:13 volumio volumio[982]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 23 12:55:13 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:13 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 209. May 23 12:55:13 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:13 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:13 volumio go-librespot[5767]: Librespot-go daemon starting... May 23 12:55:13 volumio go-librespot[5767]: time="2025-05-23T12:55:13+01:00" level=info msg="generated new device id: bed88098613fc77bf0de743a4bd172d9c5559932" May 23 12:55:13 volumio go-librespot[5767]: time="2025-05-23T12:55:13+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:14 volumio go-librespot[5767]: time="2025-05-23T12:55:14+01:00" level=debug msg="obtained new client token: AADrDdcm69mdIldR1LSpG3xBui4GU3hwf6YB8XvyqgEp+FyFbh+73zNIDy83OCYw887CcDndyhN6wAiQ4R6Pp9WY1SHcASy85ksMI4JILW+IZhtv6rYjy0qHS1Zy1dQ9Z+tkQc549IJYDro6uzKRsfBywP5IPjVt0tS/wqhAh4Uv50lXTu8ef0t6gkevpDFzm5FACQ+g6t4m5GxE8pno9idN/cuNSQf6dJz/PzPKcWCENl3hSSj4LxFAvw==" May 23 12:55:14 volumio go-librespot[5767]: time="2025-05-23T12:55:14+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]" May 23 12:55:14 volumio go-librespot[5767]: time="2025-05-23T12:55:14+01:00" level=debug msg="completed keyexchange" May 23 12:55:14 volumio go-librespot[5767]: time="2025-05-23T12:55:14+01:00" level=debug msg="completed challenge" May 23 12:55:15 volumio go-librespot[5767]: time="2025-05-23T12:55:15+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:16 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:16 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 210. May 23 12:55:18 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:18 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:18 volumio go-librespot[5775]: Librespot-go daemon starting... May 23 12:55:18 volumio go-librespot[5775]: time="2025-05-23T12:55:18+01:00" level=info msg="generated new device id: e404015720f89f31168d803e93e07be4632f74c2" May 23 12:55:18 volumio go-librespot[5775]: time="2025-05-23T12:55:18+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:18 volumio go-librespot[5775]: time="2025-05-23T12:55:18+01:00" level=debug msg="obtained new client token: AABGAWPuljc9qhFmVa/8BLgEvtYnantmofBJy0p60vIguG4AMnWN0HtcGNwukbPDjMddHtuNj8pAhmVufVSbgGxGULzb4IgbTRj1UB7vBp/z1VOGT94yVksgc+ug4FX9ziHHI5+puXsz+0AMBFZ93ke2W7DrHu3k3lyAV0uFueieX1LzPS52GRdhd402UsNx57TOyDS/JDPdEAXh4lOmDw/IeuvfTf3l0POOe4MAbd/sntuVp1VsWi38CRob" May 23 12:55:18 volumio go-librespot[5775]: time="2025-05-23T12:55:18+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]" May 23 12:55:18 volumio go-librespot[5775]: time="2025-05-23T12:55:18+01:00" level=debug msg="completed keyexchange" May 23 12:55:19 volumio go-librespot[5775]: time="2025-05-23T12:55:19+01:00" level=debug msg="completed challenge" May 23 12:55:19 volumio go-librespot[5775]: time="2025-05-23T12:55:19+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:19 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:19 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:22 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 211. May 23 12:55:22 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:22 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:22 volumio go-librespot[5783]: Librespot-go daemon starting... May 23 12:55:22 volumio go-librespot[5783]: time="2025-05-23T12:55:22+01:00" level=info msg="generated new device id: 352fcb61b2b96c1c7d185340d3ab3d6b2afe0def" May 23 12:55:22 volumio go-librespot[5783]: time="2025-05-23T12:55:22+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:22 volumio go-librespot[5783]: time="2025-05-23T12:55:22+01:00" level=debug msg="obtained new client token: AABcdUPehbVfy2+FGhejQXrLSheKe7vVsGPrX9abi56CKOzOYRzj2WGmncv58Wgge8IZrZNECcPV7j2kwnSdgHkkiBFhseIa82tYEXiB1TicNXDvoZg9wzA00vbCKxmClFVU2XcWJdv1VadLM8lqdAVFh5GIQNOmQVn/dvuT/fDhXvJmxZQOvJhcWKsaHopbBNZteNSDg1k5hvsat3fFY+fkuZG6TDlTwtcSTQ09Wm7tmxqufMu/vla9rslU" May 23 12:55:22 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:22 volumio go-librespot[5783]: time="2025-05-23T12:55:22+01:00" level=debug msg="new websocket client" May 23 12:55:22 volumio volumio[982]: info: Connection to go-librespot Websocket established May 23 12:55:22 volumio go-librespot[5783]: time="2025-05-23T12:55:22+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]" May 23 12:55:23 volumio go-librespot[5783]: time="2025-05-23T12:55:23+01:00" level=debug msg="completed keyexchange" May 23 12:55:23 volumio go-librespot[5783]: time="2025-05-23T12:55:23+01:00" level=debug msg="completed challenge" May 23 12:55:23 volumio go-librespot[5783]: time="2025-05-23T12:55:23+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:23 volumio volumio[982]: info: Connection to go-librespot Websocket closed May 23 12:55:25 volumio volumio[982]: info: Getting Spotify volume May 23 12:55:25 volumio volumio[982]: (node:982) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:25 volumio volumio[982]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 23 12:55:25 volumio volumio[982]: (node:982) 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: 73) May 23 12:55:25 volumio volumio[982]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 23 12:55:25 volumio volumio[982]: info: CoreCommandRouter::volumioGetState May 23 12:55:25 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:25 volumio volumio[982]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 23 12:55:26 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:26 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 212. May 23 12:55:26 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:26 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:26 volumio go-librespot[5805]: Librespot-go daemon starting... May 23 12:55:26 volumio go-librespot[5805]: time="2025-05-23T12:55:26+01:00" level=info msg="generated new device id: b4c0d2e52db8075da3d8110f80ebf5f15e0dfc2b" May 23 12:55:26 volumio go-librespot[5805]: time="2025-05-23T12:55:26+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:26 volumio go-librespot[5805]: time="2025-05-23T12:55:26+01:00" level=debug msg="obtained new client token: AACcfXNgdUMgwutNmFd/SEC0GAz7KmcBuqWVy1hE1TJQXrAo7jqPe/v/VeeSpcXMYrA7QRVbeC0l8DKwqRoGac3aEKfvs1VagHuTTl1362GggamR9guTMCPJPKw2vpk173Q9dPzXHPShkdwsM6ldgLzW53vNhqoiz/+LjVCEUe04KzjObG6ht930I2exXTUMloFmBG3Asj6I6Yw3PeMAePy5LJdyWUN44SZssUPMuTs1/wITuXh7TAPfvBXt" May 23 12:55:27 volumio go-librespot[5805]: time="2025-05-23T12:55:27+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]" May 23 12:55:27 volumio go-librespot[5805]: time="2025-05-23T12:55:27+01:00" level=debug msg="completed keyexchange" May 23 12:55:27 volumio go-librespot[5805]: time="2025-05-23T12:55:27+01:00" level=debug msg="completed challenge" May 23 12:55:27 volumio go-librespot[5805]: time="2025-05-23T12:55:27+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:29 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:29 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 213. May 23 12:55:30 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:30 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:30 volumio go-librespot[5817]: Librespot-go daemon starting... May 23 12:55:30 volumio go-librespot[5817]: time="2025-05-23T12:55:30+01:00" level=info msg="generated new device id: b32b3ebfdaf83bf887985397808b8639c38905a6" May 23 12:55:30 volumio go-librespot[5817]: time="2025-05-23T12:55:30+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:31 volumio go-librespot[5817]: time="2025-05-23T12:55:31+01:00" level=debug msg="obtained new client token: AAAoHf/z2D3fERRm/C5kJBDjKXyCtsq6qLvzYi8Auns5mnHG6vWQnOGDGqS+A70ghzLhRCwxYR1TSUz2Hs4GnnR6JTFjPrLlfAepMCLuLJu8FeyjnkN870GG49qXBUYY6xA2QmGyhqO7X0dUxdNGwASFPtbCOaGgaZtT98ZJb4qeQ7SNuNpRoU0JJdwqtiQGcvR+t0iRFBpg/DpZ0cpF5wEoV9YFtjFtX3wC2E+fJNg2YjqzKx6lMV3BNQ==" May 23 12:55:31 volumio go-librespot[5817]: time="2025-05-23T12:55:31+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]" May 23 12:55:31 volumio go-librespot[5817]: time="2025-05-23T12:55:31+01:00" level=debug msg="completed keyexchange" May 23 12:55:31 volumio go-librespot[5817]: time="2025-05-23T12:55:31+01:00" level=debug msg="completed challenge" May 23 12:55:32 volumio go-librespot[5817]: time="2025-05-23T12:55:32+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:32 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:32 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:35 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 214. May 23 12:55:35 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:35 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:35 volumio go-librespot[5840]: Librespot-go daemon starting... May 23 12:55:35 volumio go-librespot[5840]: time="2025-05-23T12:55:35+01:00" level=info msg="generated new device id: 1898334dda1b6f0a9226b41a40e41852a1f04767" May 23 12:55:35 volumio go-librespot[5840]: time="2025-05-23T12:55:35+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:35 volumio go-librespot[5840]: time="2025-05-23T12:55:35+01:00" level=debug msg="obtained new client token: AAAee4rB5uTXL8KoIu+Imb2FUTXEVI1RJM1gC4Hcx97o+cPd0Te2M2NRB3RP8XR5DiTCvhf4OZKQR0VNtgHPOWT7t9mUfP/WsR+MYSIqvOz2uNtGnHD8il+uESmk91H6HcGDn4QQUJHzhMEkJKIcYdoxF40awV5wpPZ5sYRCwDgDyWr2NsINkrTiNLSVSkuSxo1GWMdG21DtxpDmEpNDZjLq+XfvZdPAbN7SVLsWiUtxh2vuVFaUmH8eFfWg" May 23 12:55:35 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:35 volumio go-librespot[5840]: time="2025-05-23T12:55:35+01:00" level=debug msg="new websocket client" May 23 12:55:35 volumio volumio[982]: info: Connection to go-librespot Websocket established May 23 12:55:35 volumio go-librespot[5840]: time="2025-05-23T12:55:35+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]" May 23 12:55:35 volumio go-librespot[5840]: time="2025-05-23T12:55:35+01:00" level=debug msg="completed keyexchange" May 23 12:55:36 volumio go-librespot[5840]: time="2025-05-23T12:55:36+01:00" level=debug msg="completed challenge" May 23 12:55:36 volumio go-librespot[5840]: time="2025-05-23T12:55:36+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:36 volumio volumio[982]: info: Connection to go-librespot Websocket closed May 23 12:55:38 volumio volumio[982]: info: Getting Spotify volume May 23 12:55:38 volumio volumio[982]: (node:982) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:38 volumio volumio[982]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 23 12:55:38 volumio volumio[982]: (node:982) 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: 74) May 23 12:55:38 volumio volumio[982]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 23 12:55:38 volumio volumio[982]: info: CoreCommandRouter::volumioGetState May 23 12:55:38 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:38 volumio volumio[982]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 23 12:55:39 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:39 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 215. May 23 12:55:39 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:39 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:39 volumio go-librespot[5848]: Librespot-go daemon starting... May 23 12:55:39 volumio go-librespot[5848]: time="2025-05-23T12:55:39+01:00" level=info msg="generated new device id: 0f5c703b2ad05683cad1b99d08d86006560fcd4a" May 23 12:55:39 volumio go-librespot[5848]: time="2025-05-23T12:55:39+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:39 volumio go-librespot[5848]: time="2025-05-23T12:55:39+01:00" level=debug msg="obtained new client token: AADYxBH7UWDC2zra6lMzRL5+vuPKcORfyNLgUziLGsdS36UXzEWbkCiW2VOvh47+Y5ozAFgDkPQu/VaBVjDMcjIeVKzRanA0fP/56hE+81FmXTRMn47peUlo/7R0xKjD2C5AqeRo4kRjpL59a39z5zQB3MoAbZn5L1F6+JEMu7SBXbkrcpce3SLoGjBPEv38Zv+VWNOn8wwyEtcvEoL810c0kIj4S2+0X4nzQ0k4LIeIux+9YxjEanripZ+d" May 23 12:55:39 volumio go-librespot[5848]: time="2025-05-23T12:55:39+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]" May 23 12:55:39 volumio go-librespot[5848]: time="2025-05-23T12:55:39+01:00" level=debug msg="completed keyexchange" May 23 12:55:40 volumio go-librespot[5848]: time="2025-05-23T12:55:40+01:00" level=debug msg="completed challenge" May 23 12:55:40 volumio go-librespot[5848]: time="2025-05-23T12:55:40+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:42 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:42 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 216. May 23 12:55:43 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:43 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:43 volumio go-librespot[5856]: Librespot-go daemon starting... May 23 12:55:43 volumio go-librespot[5856]: time="2025-05-23T12:55:43+01:00" level=info msg="generated new device id: 790019a522c589bfc1f4d7129f3f31972aeb42da" May 23 12:55:43 volumio go-librespot[5856]: time="2025-05-23T12:55:43+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:43 volumio go-librespot[5856]: time="2025-05-23T12:55:43+01:00" level=debug msg="obtained new client token: AAAPuE84LYppkjQjMuyY+kojk2eGfXehBwZw6OL3e+ReCkXly7sNr/hO36+mQm4WhLmPQlYHsl4ZBTZm0v6AoyfQW4UYl+aIIdgjTzAiOiPBLv0Qckt2VoRtsqMueEXX57eX4yNYJVEzLyJXyhdtWhaZ4mplxlp21Kp3BLZcQ1iLW2iW1FK407FQm7oTYfA/DHUTLMg8RkKi/JEDU7JBbz8lWgwycKFj2+ftKjEOm3CtMKfew23xVtm6hSr+" May 23 12:55:44 volumio go-librespot[5856]: time="2025-05-23T12:55:44+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]" May 23 12:55:44 volumio go-librespot[5856]: time="2025-05-23T12:55:44+01:00" level=debug msg="completed keyexchange" May 23 12:55:44 volumio volumio[982]: info: Clearing queue after UPNP request May 23 12:55:44 volumio volumio[982]: info: CoreStateMachine::ClearQueue May 23 12:55:44 volumio volumio[982]: info: CoreStateMachine::stop May 23 12:55:44 volumio volumio[982]: info: CoreStateMachine::setConsumeUpdateService undefined May 23 12:55:44 volumio volumio[982]: info: CorePlayQueue::clearPlayQueue May 23 12:55:44 volumio volumio[982]: info: CorePlayQueue::saveQueue May 23 12:55:44 volumio volumio[982]: info: CoreCommandRouter::volumioPushState May 23 12:55:44 volumio volumio[982]: info: CoreCommandRouter::volumioPushQueue May 23 12:55:44 volumio volumio[982]: error: Upnp client error: Error: This socket has been ended by the other party May 23 12:55:44 volumio volumio[982]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 23 12:55:44 volumio go-librespot[5856]: time="2025-05-23T12:55:44+01:00" level=debug msg="completed challenge" May 23 12:55:44 volumio go-librespot[5856]: time="2025-05-23T12:55:44+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:45 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:45 volumio volumio[982]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:46 volumio volumio[982]: info: Starting UPNP Playback May 23 12:55:46 volumio volumio[982]: info: Preparing playback through UPNP May 23 12:55:46 volumio volumio[982]: info: CoreCommandRouter::volumioGetState May 23 12:55:46 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:46 volumio volumio[982]: info: CoreStateMachine::setConsumeUpdateService mpd May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 13ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 9ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 8ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 7ms May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 9ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 6ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 5ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 4ms May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 7ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 5ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 4ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 4ms May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 2ms May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 6ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 4ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 3ms May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 7ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 5ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 4ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 4ms May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: May 23 12:55:46 volumio volumio[982]: ---------------------------- MPD announces system playlist update May 23 12:55:46 volumio volumio[982]: info: Ignoring MPD Status Update May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 10ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 9ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 8ms May 23 12:55:46 volumio volumio[982]: info: ------------------------------ 4ms May 23 12:55:47 volumio volumio[982]: info: May 23 12:55:47 volumio volumio[982]: ---------------------------- MPD announces state update: player May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::getState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand status May 23 12:55:47 volumio volumio[982]: info: May 23 12:55:47 volumio volumio[982]: ---------------------------- MPD announces state update: player May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::getState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand status May 23 12:55:47 volumio volumio[982]: info: May 23 12:55:47 volumio volumio[982]: ---------------------------- MPD announces state update: player May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::getState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand status May 23 12:55:47 volumio volumio[982]: info: May 23 12:55:47 volumio volumio[982]: ---------------------------- MPD announces state update: player May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::getState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand status May 23 12:55:47 volumio volumio[982]: info: May 23 12:55:47 volumio volumio[982]: ---------------------------- MPD announces state update: player May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand status took 19 milliseconds May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::getState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand status May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand status took 16 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand status took 12 milliseconds May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 23 12:55:47 volumio volumio[982]: info: May 23 12:55:47 volumio volumio[982]: ---------------------------- MPD announces state update: player May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::getState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand status May 23 12:55:47 volumio volumio[982]: info: May 23 12:55:47 volumio volumio[982]: ---------------------------- MPD announces state update: player May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::getState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand status May 23 12:55:47 volumio volumio[982]: info: May 23 12:55:47 volumio volumio[982]: ---------------------------- MPD announces state update: player May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::getState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand status May 23 12:55:47 volumio volumio[982]: info: FusionDsp - ---- read samplerate, raw: 48000,S32_LE,2,32 May 23 12:55:47 volumio volumio[982]: info: FusionDsp - ---- read samplerate from file: 48000 May 23 12:55:47 volumio volumio[982]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand status took 41 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand status took 35 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand playlistinfo took 30 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand playlistinfo took 29 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand playlistinfo took 27 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand status took 23 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand status took 21 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand status took 20 milliseconds May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseTrackInfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseTrackInfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseTrackInfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseState May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::pushState May 23 12:55:47 volumio volumio[982]: info: CoreCommandRouter::servicePushState May 23 12:55:47 volumio volumio[982]: verbose: In UPNP mode May 23 12:55:47 volumio volumio[982]: verbose: STATE SERVICE {"status":"play","position":1,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"bbc_radio_two-audio%3d96000.m3u8","artist":null,"album":null,"uri":"http://as-hls-ww-live.akamaized.net/pool_74208725/live/ww/bbc_radio_two/bbc_radio_two.isml/bbc_radio_two-audio%3d96000.m3u8","trackType":"m3u8"} May 23 12:55:47 volumio volumio[982]: verbose: CURRENT POSITION 0 May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState stateService play May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState currentStatus stop May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::pushState May 23 12:55:47 volumio volumio[982]: info: CoreCommandRouter::servicePushState May 23 12:55:47 volumio volumio[982]: verbose: In UPNP mode May 23 12:55:47 volumio volumio[982]: verbose: STATE SERVICE {"status":"play","position":1,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"bbc_radio_two-audio%3d96000.m3u8","artist":null,"album":null,"uri":"http://as-hls-ww-live.akamaized.net/pool_74208725/live/ww/bbc_radio_two/bbc_radio_two.isml/bbc_radio_two-audio%3d96000.m3u8","trackType":"m3u8"} May 23 12:55:47 volumio volumio[982]: verbose: CURRENT POSITION 0 May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState stateService play May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState currentStatus play May 23 12:55:47 volumio volumio[982]: info: Received an update from plugin. extracting info from payload May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::pushState May 23 12:55:47 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::pushState May 23 12:55:47 volumio volumio[982]: info: CoreCommandRouter::servicePushState May 23 12:55:47 volumio volumio[982]: verbose: In UPNP mode May 23 12:55:47 volumio volumio[982]: verbose: STATE SERVICE {"status":"play","position":1,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"bbc_radio_two-audio%3d96000.m3u8","artist":null,"album":null,"uri":"http://as-hls-ww-live.akamaized.net/pool_74208725/live/ww/bbc_radio_two/bbc_radio_two.isml/bbc_radio_two-audio%3d96000.m3u8","trackType":"m3u8"} May 23 12:55:47 volumio volumio[982]: verbose: CURRENT POSITION 0 May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState stateService play May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState currentStatus play May 23 12:55:47 volumio volumio[982]: info: Received an update from plugin. extracting info from payload May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::pushState May 23 12:55:47 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:47 volumio volumio[982]: info: ------------------------------ 98ms May 23 12:55:47 volumio volumio[982]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 23 12:55:47 volumio volumio[982]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 23 12:55:47 volumio volumio[982]: info: ------------------------------ 93ms May 23 12:55:47 volumio volumio[982]: info: ------------------------------ 90ms May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand playlistinfo took 36 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand playlistinfo took 37 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand playlistinfo took 31 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand playlistinfo took 31 milliseconds May 23 12:55:47 volumio volumio[982]: info: sendMpdCommand playlistinfo took 30 milliseconds May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseTrackInfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseTrackInfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseTrackInfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseTrackInfo May 23 12:55:47 volumio volumio[982]: verbose: ControllerMpd::parseTrackInfo May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::pushState May 23 12:55:47 volumio volumio[982]: info: CoreCommandRouter::servicePushState May 23 12:55:47 volumio volumio[982]: verbose: In UPNP mode May 23 12:55:47 volumio volumio[982]: verbose: STATE SERVICE {"status":"play","position":1,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"bbc_radio_two-audio%3d96000.m3u8","artist":null,"album":null,"uri":"http://as-hls-ww-live.akamaized.net/pool_74208725/live/ww/bbc_radio_two/bbc_radio_two.isml/bbc_radio_two-audio%3d96000.m3u8","trackType":"m3u8"} May 23 12:55:47 volumio volumio[982]: verbose: CURRENT POSITION 0 May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState stateService play May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState currentStatus play May 23 12:55:47 volumio volumio[982]: info: Received an update from plugin. extracting info from payload May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::pushState May 23 12:55:47 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::pushState May 23 12:55:47 volumio volumio[982]: info: CoreCommandRouter::servicePushState May 23 12:55:47 volumio volumio[982]: verbose: In UPNP mode May 23 12:55:47 volumio volumio[982]: verbose: STATE SERVICE {"status":"play","position":1,"seek":1134,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"bbc_radio_two-audio%3d96000.m3u8","artist":null,"album":null,"uri":"http://as-hls-ww-live.akamaized.net/pool_74208725/live/ww/bbc_radio_two/bbc_radio_two.isml/bbc_radio_two-audio%3d96000.m3u8","trackType":"m3u8"} May 23 12:55:47 volumio volumio[982]: verbose: CURRENT POSITION 0 May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState stateService play May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState currentStatus play May 23 12:55:47 volumio volumio[982]: info: Received an update from plugin. extracting info from payload May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::pushState May 23 12:55:47 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::pushState May 23 12:55:47 volumio volumio[982]: info: CoreCommandRouter::servicePushState May 23 12:55:47 volumio volumio[982]: verbose: In UPNP mode May 23 12:55:47 volumio volumio[982]: verbose: STATE SERVICE {"status":"play","position":1,"seek":1438,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"bbc_radio_two-audio%3d96000.m3u8","artist":null,"album":null,"uri":"http://as-hls-ww-live.akamaized.net/pool_74208725/live/ww/bbc_radio_two/bbc_radio_two.isml/bbc_radio_two-audio%3d96000.m3u8","trackType":"m3u8"} May 23 12:55:47 volumio volumio[982]: verbose: CURRENT POSITION 0 May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState stateService play May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState currentStatus play May 23 12:55:47 volumio volumio[982]: info: Received an update from plugin. extracting info from payload May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::pushState May 23 12:55:47 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::pushState May 23 12:55:47 volumio volumio[982]: info: CoreCommandRouter::servicePushState May 23 12:55:47 volumio volumio[982]: verbose: In UPNP mode May 23 12:55:47 volumio volumio[982]: verbose: STATE SERVICE {"status":"play","position":1,"seek":1480,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"bbc_radio_two-audio%3d96000.m3u8","artist":null,"album":null,"uri":"http://as-hls-ww-live.akamaized.net/pool_74208725/live/ww/bbc_radio_two/bbc_radio_two.isml/bbc_radio_two-audio%3d96000.m3u8","trackType":"m3u8"} May 23 12:55:47 volumio volumio[982]: verbose: CURRENT POSITION 0 May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState stateService play May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState currentStatus play May 23 12:55:47 volumio volumio[982]: info: Received an update from plugin. extracting info from payload May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::pushState May 23 12:55:47 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:47 volumio volumio[982]: info: ControllerMpd::pushState May 23 12:55:47 volumio volumio[982]: info: CoreCommandRouter::servicePushState May 23 12:55:47 volumio volumio[982]: verbose: In UPNP mode May 23 12:55:47 volumio volumio[982]: verbose: STATE SERVICE {"status":"play","position":1,"seek":1480,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"bbc_radio_two-audio%3d96000.m3u8","artist":null,"album":null,"uri":"http://as-hls-ww-live.akamaized.net/pool_74208725/live/ww/bbc_radio_two/bbc_radio_two.isml/bbc_radio_two-audio%3d96000.m3u8","trackType":"m3u8"} May 23 12:55:47 volumio volumio[982]: verbose: CURRENT POSITION 0 May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState stateService play May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::syncState currentStatus play May 23 12:55:47 volumio volumio[982]: info: Received an update from plugin. extracting info from payload May 23 12:55:47 volumio volumio[982]: info: CoreStateMachine::pushState May 23 12:55:47 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:47 volumio volumio[982]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 23 12:55:47 volumio volumio[982]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 23 12:55:47 volumio volumio[982]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 23 12:55:47 volumio volumio[982]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 23 12:55:47 volumio volumio[982]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 23 12:55:47 volumio volumio[982]: info: ------------------------------ 116ms May 23 12:55:47 volumio volumio[982]: info: ------------------------------ 113ms May 23 12:55:47 volumio volumio[982]: info: ------------------------------ 96ms May 23 12:55:47 volumio volumio[982]: info: ------------------------------ 93ms May 23 12:55:47 volumio volumio[982]: info: ------------------------------ 90ms May 23 12:55:47 volumio volumio[982]: info: FusionDsp - eq1: May 23 12:55:47 volumio volumio[982]: type: Biquad May 23 12:55:47 volumio volumio[982]: parameters: May 23 12:55:47 volumio volumio[982]: type: Lowshelf May 23 12:55:47 volumio volumio[982]: freq: 185 May 23 12:55:47 volumio volumio[982]: q: 0.82 May 23 12:55:47 volumio volumio[982]: gain: 0 May 23 12:55:47 volumio volumio[982]: eq2: May 23 12:55:47 volumio volumio[982]: type: Biquad May 23 12:55:47 volumio volumio[982]: parameters: May 23 12:55:47 volumio volumio[982]: type: Peaking May 23 12:55:47 volumio volumio[982]: freq: 1300 May 23 12:55:47 volumio volumio[982]: q: 0.4 May 23 12:55:47 volumio volumio[982]: gain: 0 May 23 12:55:47 volumio volumio[982]: eq3: May 23 12:55:47 volumio volumio[982]: type: Biquad May 23 12:55:47 volumio volumio[982]: parameters: May 23 12:55:47 volumio volumio[982]: type: Highshelf May 23 12:55:47 volumio volumio[982]: freq: 5500 May 23 12:55:47 volumio volumio[982]: q: 0.82 May 23 12:55:47 volumio volumio[982]: gain: 0 May 23 12:55:47 volumio volumio[982]: info: FusionDsp - {"Reload":{"result":"Ok"}} May 23 12:55:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 23 12:55:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 217. May 23 12:55:47 volumio systemd[1]: Stopped go-librespot Daemon. May 23 12:55:47 volumio systemd[1]: Started go-librespot Daemon. May 23 12:55:47 volumio go-librespot[5893]: Librespot-go daemon starting... May 23 12:55:47 volumio go-librespot[5893]: time="2025-05-23T12:55:47+01:00" level=info msg="generated new device id: ace019ba7a087add0aa53af17285208743434d75" May 23 12:55:47 volumio go-librespot[5893]: time="2025-05-23T12:55:47+01:00" level=debug msg="stored credentials found for gsx550man" May 23 12:55:48 volumio go-librespot[5893]: time="2025-05-23T12:55:48+01:00" level=debug msg="obtained new client token: AABZc4e2+npmS+8cPBfhksdGFAC6jAJ9qh5KvmC9X4DIGJCRexkFm6U2/ZwmpC/UVOAJx/AVC+KH18UJ7JmxllonRblM+3jOmtH46SGgbrX+VINjQE64UovuzairCbUZL3YHXhUILxVsfF1FuVS5x6IgBdjls+Ho4VzXDjMzHhETW3okMtiXEmpcTyggkyURm21XQfffIkqm1hfn8QOoMdAy7+WHb2ZFvNvqmUi3fKyqe+vA3psV/m2nWg==" May 23 12:55:48 volumio volumio[982]: info: Initializing connection to go-librespot Websocket May 23 12:55:48 volumio go-librespot[5893]: time="2025-05-23T12:55:48+01:00" level=debug msg="new websocket client" May 23 12:55:48 volumio volumio[982]: info: Connection to go-librespot Websocket established May 23 12:55:48 volumio go-librespot[5893]: time="2025-05-23T12:55:48+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]" May 23 12:55:48 volumio go-librespot[5893]: time="2025-05-23T12:55:48+01:00" level=debug msg="completed keyexchange" May 23 12:55:48 volumio go-librespot[5893]: time="2025-05-23T12:55:48+01:00" level=debug msg="completed challenge" May 23 12:55:49 volumio go-librespot[5893]: time="2025-05-23T12:55:49+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" May 23 12:55:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 23 12:55:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 23 12:55:49 volumio volumio[982]: info: Connection to go-librespot Websocket closed May 23 12:55:51 volumio volumio[982]: info: Getting Spotify volume May 23 12:55:51 volumio volumio[982]: (node:982) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 23 12:55:51 volumio volumio[982]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 23 12:55:51 volumio volumio[982]: (node:982) 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: 75) May 23 12:55:51 volumio volumio[982]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 23 12:55:51 volumio volumio[982]: info: CoreCommandRouter::volumioGetState May 23 12:55:51 volumio volumio[982]: info: CorePlayQueue::getTrack 0 May 23 12:55:51 volumio volumio[982]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 23 12:55:51 volumio volumio[982]: TypeError: Cannot read property 'name' of undefined May 23 12:55:51 volumio volumio[982]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) May 23 12:55:51 volumio volumio[982]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) May 23 12:55:51 volumio volumio[982]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:58:38) May 23 12:55:51 volumio volumio[982]: at Socket.emit (events.js:315:20) May 23 12:55:51 volumio volumio[982]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 May 23 12:55:51 volumio volumio[982]: at processTicksAndRejections (internal/process/task_queues.js:75:11) May 23 12:55:51 volumio volumio[982]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 23 12:55:51 volumio sudo[5931]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-23 12:54 May 23 12:55:51 volumio sudo[5931]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"