-- Logs begin at Thu 2019-02-14 12:11:59 EET, end at Fri 2024-07-19 14:01:59 EEST. -- Jul 19 14:00:02 chm-volumio volumio[930]: info: Getting Spotify volume Jul 19 14:00:02 chm-volumio volumio[930]: (node:930) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:02 chm-volumio volumio[930]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 19 14:00:02 chm-volumio volumio[930]: (node:930) 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: 135) Jul 19 14:00:02 chm-volumio volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:00:02 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:02 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:00:02 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:02 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:02 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:02 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 194. Jul 19 14:00:02 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:02 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:02 chm-volumio go-librespot[7453]: Librespot-go daemon starting... Jul 19 14:00:02 chm-volumio go-librespot[7453]: time="2024-07-19T14:00:02+03:00" level=info msg="generated new device id: fc93b1b344c4b14a144f14f75698b3ff8029cc43" Jul 19 14:00:02 chm-volumio go-librespot[7453]: time="2024-07-19T14:00:02+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:03 chm-volumio go-librespot[7453]: time="2024-07-19T14:00:03+03:00" level=debug msg="obtained new client token: AABqk7woqh4CNHE8feBqkBqOb0sF3xMFGbPQXdFZh6oJEVz5QdAX3wEErHHn7mBTARBtmwLsGSn0euByfcKVk11ADrN90c8rAMKxeWlasp9ckCBSodsteOOS3XeAkVFMSvrH2THhLpIUj2mZargq2YCryDez7XBVhO6C9NaWMp2H2E9S7b1zyDfvJpC6hF1akhxOICUotij3DVCImAlUZ6tYWCl/iwWbtq9kotQBPOfxlQniTfmeVnNTrS+S" Jul 19 14:00:03 chm-volumio go-librespot[7453]: time="2024-07-19T14:00:03+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:00:03 chm-volumio go-librespot[7453]: time="2024-07-19T14:00:03+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:03 chm-volumio go-librespot[7453]: time="2024-07-19T14:00:03+03:00" level=debug msg="completed challenge" Jul 19 14:00:04 chm-volumio go-librespot[7453]: time="2024-07-19T14:00:04+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:04 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:04 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:05 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:05 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:07 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:07 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 195. Jul 19 14:00:07 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:07 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:07 chm-volumio go-librespot[7463]: Librespot-go daemon starting... Jul 19 14:00:07 chm-volumio go-librespot[7463]: time="2024-07-19T14:00:07+03:00" level=info msg="generated new device id: 0bd54ab916c2fb26df144ec60baf2906b2b5f37e" Jul 19 14:00:07 chm-volumio go-librespot[7463]: time="2024-07-19T14:00:07+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:07 chm-volumio go-librespot[7463]: time="2024-07-19T14:00:07+03:00" level=debug msg="obtained new client token: AAByHOOw6tQdA7yCNsAuX0pMsLq/fQaQvu9E+NhXo+J7FQpC+GMC9pB6jysQS3AnBOnJeL/yblQkPOKnRQFylbZjFXQC+UG+e1yDIJGH+P+HU4rgLBdrLcDhhoPl6FZcTEF2wlgBrD4mxV+2Hl79zpjwR//lmf35VFv9khytNOSb1BIYNb+uWLTNNp6CJx/DYVte0d5pf+oImKy8SvRmK9uQxb5d9QXJNK3tmXkch7yMNM2MJMVPUOC3ILKUHQ0=" Jul 19 14:00:07 chm-volumio go-librespot[7463]: time="2024-07-19T14:00:07+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 19 14:00:07 chm-volumio go-librespot[7463]: time="2024-07-19T14:00:07+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:08 chm-volumio go-librespot[7463]: time="2024-07-19T14:00:08+03:00" level=debug msg="completed challenge" Jul 19 14:00:08 chm-volumio go-librespot[7463]: time="2024-07-19T14:00:08+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:08 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:08 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:08 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:08 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:11 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:11 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 196. Jul 19 14:00:11 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:11 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:11 chm-volumio go-librespot[7472]: Librespot-go daemon starting... Jul 19 14:00:11 chm-volumio go-librespot[7472]: time="2024-07-19T14:00:11+03:00" level=info msg="generated new device id: 634a7044fdbce91602e13dd7b0a0b05f94174c31" Jul 19 14:00:11 chm-volumio go-librespot[7472]: time="2024-07-19T14:00:11+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:11 chm-volumio go-librespot[7472]: time="2024-07-19T14:00:11+03:00" level=debug msg="obtained new client token: AACj4FIOicM0cfsbJfagxwxQuZI5v+byvTlJJLxhEAxVwCIleb74QNgBuCxM+UG3eh1zqKblXvie7VJ5znxxDnDWR0Y7AVzQVNeNT/FwjbD2P5mV8UuQwSRhd+X2HLOvPjRogZrQALH6QOrZr9/Qa10VBd8vvAMc6u8DTCM3u32XC5LUxgl0AGuVoQLASPktBQA+8UuQG9vgCeYL4j+WAwd84DcoMIqZ8A/A0f+40wcchiu48jpeEZaagVpgnps=" Jul 19 14:00:11 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:11 chm-volumio volumio[930]: info: Connection to go-librespot Websocket established Jul 19 14:00:11 chm-volumio go-librespot[7472]: time="2024-07-19T14:00:11+03:00" level=debug msg="new websocket client" Jul 19 14:00:11 chm-volumio go-librespot[7472]: time="2024-07-19T14:00:11+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:00:11 chm-volumio go-librespot[7472]: time="2024-07-19T14:00:11+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:12 chm-volumio go-librespot[7472]: time="2024-07-19T14:00:12+03:00" level=debug msg="completed challenge" Jul 19 14:00:12 chm-volumio go-librespot[7472]: time="2024-07-19T14:00:12+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:12 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:12 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:12 chm-volumio volumio[930]: info: Connection to go-librespot Websocket closed Jul 19 14:00:14 chm-volumio volumio[930]: info: Getting Spotify volume Jul 19 14:00:14 chm-volumio volumio[930]: (node:930) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:14 chm-volumio volumio[930]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 19 14:00:14 chm-volumio volumio[930]: (node:930) 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: 136) Jul 19 14:00:14 chm-volumio volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:00:14 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:14 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:00:15 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:15 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:15 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:15 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 197. Jul 19 14:00:15 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:15 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:15 chm-volumio go-librespot[7480]: Librespot-go daemon starting... Jul 19 14:00:15 chm-volumio go-librespot[7480]: time="2024-07-19T14:00:15+03:00" level=info msg="generated new device id: 724be1443498d83df8c7b680b32347727cd3513a" Jul 19 14:00:15 chm-volumio go-librespot[7480]: time="2024-07-19T14:00:15+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:15 chm-volumio go-librespot[7480]: time="2024-07-19T14:00:15+03:00" level=debug msg="obtained new client token: AAAzGhUFBD1b3jyVgCHtHnvz6kYIgk1Fi8Voj8usooaQb7YlhwhfhiZGWZCBjauqYEVRyuzZNZ3wDlaE+LwPYK3Wm+jtnP82OcKyUO3CjYVrvn3kX2BWG4SxtOgXbGcrLc+P2F3+mJtZw0q04Q6OZ0D7x5PhAMJM0g23W3a2LZ64w/SEnuWv+0GQe38Mk4CIjv7S5Er8a21S6U69JTclLUNIv4sLBEO5MwFuG+T+NKVe/h7GslzDxdFhEnrDa3c=" Jul 19 14:00:16 chm-volumio go-librespot[7480]: time="2024-07-19T14:00:16+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 19 14:00:16 chm-volumio go-librespot[7480]: time="2024-07-19T14:00:16+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:16 chm-volumio go-librespot[7480]: time="2024-07-19T14:00:16+03:00" level=debug msg="completed challenge" Jul 19 14:00:16 chm-volumio go-librespot[7480]: time="2024-07-19T14:00:16+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:16 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:16 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:18 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:18 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:19 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:19 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 198. Jul 19 14:00:19 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:19 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:19 chm-volumio go-librespot[7488]: Librespot-go daemon starting... Jul 19 14:00:19 chm-volumio go-librespot[7488]: time="2024-07-19T14:00:19+03:00" level=info msg="generated new device id: 543422d806f22ff487cad7c6f216503efbf36792" Jul 19 14:00:19 chm-volumio go-librespot[7488]: time="2024-07-19T14:00:19+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:20 chm-volumio go-librespot[7488]: time="2024-07-19T14:00:20+03:00" level=debug msg="obtained new client token: AACpXyObHfYV4FoRU8TzMEizoYkkvoL5q8R5XTY8muxrMsx3786ALFjh0PGfCe91LzlohI5mXbDtSwZsvaksTtasCM9ko7HIMbK6QIb5PtACCNWki5lFAG1YV/D6nzRunUhVAVtFGtT7EGQmBatWrSkBlMEvvIFXIvd2oxETjTL4Q0FB7FTqlH0WpcWrt7u3YpXyKbIs0ySBMLPBaCnb14c1bM6eZ7n82Thq7kdUhyhTW2kEWKoJRoIunw5m" Jul 19 14:00:20 chm-volumio go-librespot[7488]: time="2024-07-19T14:00:20+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 19 14:00:20 chm-volumio go-librespot[7488]: time="2024-07-19T14:00:20+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:20 chm-volumio go-librespot[7488]: time="2024-07-19T14:00:20+03:00" level=debug msg="completed challenge" Jul 19 14:00:21 chm-volumio go-librespot[7488]: time="2024-07-19T14:00:21+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:21 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:21 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:21 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:21 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:24 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:24 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 199. Jul 19 14:00:24 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:24 chm-volumio ntpd[753]: Soliciting pool server 2606:4700:f1::1 Jul 19 14:00:24 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:24 chm-volumio go-librespot[7497]: Librespot-go daemon starting... Jul 19 14:00:24 chm-volumio go-librespot[7497]: time="2024-07-19T14:00:24+03:00" level=info msg="generated new device id: 28b8d2751f5b8d869a40d09e1453397d0f89c3e2" Jul 19 14:00:24 chm-volumio go-librespot[7497]: time="2024-07-19T14:00:24+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:24 chm-volumio go-librespot[7497]: time="2024-07-19T14:00:24+03:00" level=debug msg="obtained new client token: AAANAm5zbzaAu6ZfDe+Qz7c8yL1Hb7AulE1b0l3tuBh4zqHiEe9GR3eioLlXODjbVT1Yb6QZUdBcLJhxCHs1kDSN2iywGSdFizf+pXPkMSGtsTIUlJNlpeUn2qP/a7/fTFt+3RZVyqOKenLkoIVlgFZ3w1P94f2fKdijPoRPAwHAq0N9ysBtSYcPC+DGY/zaLjXf9w/GIiK8tGUHyhkXXYHxKlWbPdHh3ziwnYRbBhSSIv+s+PfskE1A2pkWcC8=" Jul 19 14:00:24 chm-volumio go-librespot[7497]: time="2024-07-19T14:00:24+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 19 14:00:24 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:24 chm-volumio go-librespot[7497]: time="2024-07-19T14:00:24+03:00" level=debug msg="new websocket client" Jul 19 14:00:24 chm-volumio volumio[930]: info: Connection to go-librespot Websocket established Jul 19 14:00:24 chm-volumio go-librespot[7497]: time="2024-07-19T14:00:24+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:25 chm-volumio go-librespot[7497]: time="2024-07-19T14:00:25+03:00" level=debug msg="completed challenge" Jul 19 14:00:25 chm-volumio go-librespot[7497]: time="2024-07-19T14:00:25+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:25 chm-volumio volumio[930]: info: Connection to go-librespot Websocket closed Jul 19 14:00:25 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:25 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:27 chm-volumio volumio[930]: info: Getting Spotify volume Jul 19 14:00:27 chm-volumio volumio[930]: (node:930) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:27 chm-volumio volumio[930]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 19 14:00:27 chm-volumio volumio[930]: (node:930) 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: 137) Jul 19 14:00:27 chm-volumio volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:00:27 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:27 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:00:28 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:28 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:28 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:28 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 200. Jul 19 14:00:28 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:28 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:28 chm-volumio go-librespot[7505]: Librespot-go daemon starting... Jul 19 14:00:28 chm-volumio go-librespot[7505]: time="2024-07-19T14:00:28+03:00" level=info msg="generated new device id: f4788126da9a0ab7d6e4607b7ca2e0457cb281dc" Jul 19 14:00:28 chm-volumio go-librespot[7505]: time="2024-07-19T14:00:28+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:28 chm-volumio go-librespot[7505]: time="2024-07-19T14:00:28+03:00" level=debug msg="obtained new client token: AAAQih2BUTHB1AP5+MVSEfC+iZJbb/bDctmRX03id0aI8aw+LbTL3L/S0OA6OWmBWKFQl3YtN+/52+MnDvA+dGa/kiiMPbjFvqpQ9qWuLxgUny6sVjOzdnQm/ICmNOUSG0FR0LtL2NfXlIStAXlkzU/lRbip19LJsqeIK57A1hneaskma69MYnfgCQ0PBjnyeFpHgLoyDe9mWbUJI6umBEOm5/Xe63qqMzSA2cQaWY+Wz/wXcpSqol270ngwOG8=" Jul 19 14:00:28 chm-volumio go-librespot[7505]: time="2024-07-19T14:00:28+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:00:28 chm-volumio go-librespot[7505]: time="2024-07-19T14:00:28+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:29 chm-volumio go-librespot[7505]: time="2024-07-19T14:00:29+03:00" level=debug msg="completed challenge" Jul 19 14:00:29 chm-volumio go-librespot[7505]: time="2024-07-19T14:00:29+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:29 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:29 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:31 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:31 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:32 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:32 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 201. Jul 19 14:00:32 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:32 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:32 chm-volumio go-librespot[7513]: Librespot-go daemon starting... Jul 19 14:00:32 chm-volumio go-librespot[7513]: time="2024-07-19T14:00:32+03:00" level=info msg="generated new device id: c55d23a61dc63a76ae3b969d6fdc6e75b8dee501" Jul 19 14:00:32 chm-volumio go-librespot[7513]: time="2024-07-19T14:00:32+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:32 chm-volumio go-librespot[7513]: time="2024-07-19T14:00:32+03:00" level=debug msg="obtained new client token: AAAHuqc99HgTh3ov8G5Sa7ILgMjGkCooQcChvmg0HYSTgNVHRlQVFmI7r+ZdmxNtmUGtsVT/zwDQVkdHIYW5pwLuveOUcpe2DvuzGU/azPUTXzhvkrohnEpM2VmconOySSglWwU5XzWoQR0mbe+yjV8ugKnmCY40pglTW9BMgAYBj3rT08myVdPggqKYLMWY+tHe4ggnssAR/6mFSjtRnHuwrDLmjYx1Lh0xt+hQ5itfzxTGmSfN4vLf0zztbl0=" Jul 19 14:00:33 chm-volumio go-librespot[7513]: time="2024-07-19T14:00:33+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:00:33 chm-volumio go-librespot[7513]: time="2024-07-19T14:00:33+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:33 chm-volumio go-librespot[7513]: time="2024-07-19T14:00:33+03:00" level=debug msg="completed challenge" Jul 19 14:00:33 chm-volumio go-librespot[7513]: time="2024-07-19T14:00:33+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:33 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:33 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:34 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:34 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:36 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:36 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 202. Jul 19 14:00:36 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:36 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:36 chm-volumio go-librespot[7522]: Librespot-go daemon starting... Jul 19 14:00:36 chm-volumio go-librespot[7522]: time="2024-07-19T14:00:36+03:00" level=info msg="generated new device id: 5dfffb4aaa938ffff566c57aa5f3283b17604073" Jul 19 14:00:36 chm-volumio go-librespot[7522]: time="2024-07-19T14:00:36+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:37 chm-volumio go-librespot[7522]: time="2024-07-19T14:00:37+03:00" level=debug msg="obtained new client token: AAAH+p3hqUTDv4q2jtb9+gq3cin4E2jSW14OSmjFecYU/fFoBsP9EO0TvhSFMD38/k7fMwflSlmstlMthpRmhSOu654V7RyKnIZkfnUhuVJAZMJ0mqJ1+wH8UQfNdN9evmZi5MTJZkxQQdoPC7L491IV5Q9aOdL3xilsoxX/4//ZfuGr0UsZHP2PW5cM7QFV7q0OnjRAl8OsKDIquB8NvHQ909aYOfLtVvQ8kPS3bbNfvObm/Qwnkuu35Yu5" Jul 19 14:00:37 chm-volumio go-librespot[7522]: time="2024-07-19T14:00:37+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:00:37 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:37 chm-volumio volumio[930]: info: Connection to go-librespot Websocket established Jul 19 14:00:37 chm-volumio go-librespot[7522]: time="2024-07-19T14:00:37+03:00" level=debug msg="new websocket client" Jul 19 14:00:37 chm-volumio go-librespot[7522]: time="2024-07-19T14:00:37+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:37 chm-volumio go-librespot[7522]: time="2024-07-19T14:00:37+03:00" level=debug msg="completed challenge" Jul 19 14:00:38 chm-volumio go-librespot[7522]: time="2024-07-19T14:00:38+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:38 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:38 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:38 chm-volumio volumio[930]: info: Connection to go-librespot Websocket closed Jul 19 14:00:40 chm-volumio volumio[930]: info: Getting Spotify volume Jul 19 14:00:40 chm-volumio volumio[930]: (node:930) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:40 chm-volumio volumio[930]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 19 14:00:40 chm-volumio volumio[930]: (node:930) 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: 138) Jul 19 14:00:40 chm-volumio volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:00:40 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:40 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:00:41 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:41 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:41 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:41 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 203. Jul 19 14:00:41 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:41 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:41 chm-volumio go-librespot[7532]: Librespot-go daemon starting... Jul 19 14:00:41 chm-volumio go-librespot[7532]: time="2024-07-19T14:00:41+03:00" level=info msg="generated new device id: c3d02661c8d8382c0d79ac2f9e09d28d55ea5763" Jul 19 14:00:41 chm-volumio go-librespot[7532]: time="2024-07-19T14:00:41+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:41 chm-volumio go-librespot[7532]: time="2024-07-19T14:00:41+03:00" level=debug msg="obtained new client token: AADa+SdbqmXSVEeUV5tBAGEU8+GrUlcLAUda3cW9Y4mgZUqMJERJ6P3xs1BMX606hJe5ykeJf8w3mF0QzsAco2R13GCMtPnnzJPrX/oF+ucYvCKS6YAAHfzSWZPmmdwhSj5mlDeIOyL/ABIc1WnbwL4k6Dvm53QqhC0zjLLWT+omKafADrNaL5DKO/4del1CxWeaIDEHKoWIIspN9IYcz5qmnMxkMdY20MCe6Cmuj5E2KsvvYEQZ+fKwBsxNadA=" Jul 19 14:00:41 chm-volumio go-librespot[7532]: time="2024-07-19T14:00:41+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:00:41 chm-volumio go-librespot[7532]: time="2024-07-19T14:00:41+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:42 chm-volumio go-librespot[7532]: time="2024-07-19T14:00:42+03:00" level=debug msg="completed challenge" Jul 19 14:00:42 chm-volumio go-librespot[7532]: time="2024-07-19T14:00:42+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:42 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:42 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:44 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:44 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:45 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:45 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 204. Jul 19 14:00:45 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:45 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:45 chm-volumio go-librespot[7540]: Librespot-go daemon starting... Jul 19 14:00:45 chm-volumio go-librespot[7540]: time="2024-07-19T14:00:45+03:00" level=info msg="generated new device id: 780bd924c85fc4b82fb9d7c031cec055c322b939" Jul 19 14:00:45 chm-volumio go-librespot[7540]: time="2024-07-19T14:00:45+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:45 chm-volumio go-librespot[7540]: time="2024-07-19T14:00:45+03:00" level=debug msg="obtained new client token: AAD74iXOpKMrsM+jj0QW9tot4FJcjSp6p9bUbc5h/Gh4cTxNLt0HP2TxXxHXlW+utOrRb1hCiL2zX1yYehQquA7JdF5FXyEv8NeaXEmfGzraXaHQ8y31P49iOQ/kW/6W8OffHd1OT3xhpwDlRK6QE8IDDZS5LxdgsSFwpoDTyJNZwzaSJcDHtMd3OggVZbVGBHWm01Uybbgb9wbBMsMEGW/kAaH+z53oHl0yO4F0LNi2uehlbrc4zgt3KUIXYKs=" Jul 19 14:00:45 chm-volumio go-librespot[7540]: time="2024-07-19T14:00:45+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:00:45 chm-volumio go-librespot[7540]: time="2024-07-19T14:00:45+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:46 chm-volumio go-librespot[7540]: time="2024-07-19T14:00:46+03:00" level=debug msg="completed challenge" Jul 19 14:00:46 chm-volumio go-librespot[7540]: time="2024-07-19T14:00:46+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:46 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:46 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:47 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:47 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:48 chm-volumio volumio[930]: info: [yt-cast-receiver] Connecting sender through DIAL... Jul 19 14:00:49 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:49 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 205. Jul 19 14:00:49 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:49 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:49 chm-volumio go-librespot[7548]: Librespot-go daemon starting... Jul 19 14:00:49 chm-volumio go-librespot[7548]: time="2024-07-19T14:00:49+03:00" level=info msg="generated new device id: e17d103ed10481b8227a63ddce2778b7f390d9ed" Jul 19 14:00:49 chm-volumio go-librespot[7548]: time="2024-07-19T14:00:49+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:49 chm-volumio go-librespot[7548]: time="2024-07-19T14:00:49+03:00" level=debug msg="obtained new client token: AACbR0aFiWDa6rWGms+3uE4HugM6NDwdGGCLN1bF29NVGFUac9QvDSSAGvLPUXXTokV2wpaaXTn2aC+DuIC71Qf3WfSsr/tUkOl8MtJ3EIaFIuSet7uyHQ4zHGgfn/CZmD3LsVA+RLQ0Uc6bmmu+3QXxF/iJ5OXhy5BiCTI5UxRllgVGex/SZIr26Og90b8ODktb4T8P8Q2pH/LeZ6GkCYI/m5e1xjDQbHfIMBDGNp1Gpxwf212wTCiX3n1e5ZA=" Jul 19 14:00:50 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:50 chm-volumio volumio[930]: info: Connection to go-librespot Websocket established Jul 19 14:00:50 chm-volumio go-librespot[7548]: time="2024-07-19T14:00:50+03:00" level=debug msg="new websocket client" Jul 19 14:00:50 chm-volumio go-librespot[7548]: time="2024-07-19T14:00:50+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:00:50 chm-volumio go-librespot[7548]: time="2024-07-19T14:00:50+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:50 chm-volumio volumiologrotate[589]: ls: cannot access '/var/log/samba/log.wb-CHM': No such file or directory Jul 19 14:00:50 chm-volumio volumiologrotate[589]: ls: cannot access 'VOLUMIO': No such file or directory Jul 19 14:00:50 chm-volumio go-librespot[7548]: time="2024-07-19T14:00:50+03:00" level=debug msg="completed challenge" Jul 19 14:00:50 chm-volumio go-librespot[7548]: time="2024-07-19T14:00:50+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:50 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:50 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:50 chm-volumio volumio[930]: info: Connection to go-librespot Websocket closed Jul 19 14:00:52 chm-volumio volumio[930]: info: [yt-cast-receiver] (YouTube) Sender connected: Desktop (user: Sofoklis) Jul 19 14:00:52 chm-volumio volumio[930]: info: [ytcr] ***** Sender connected ***** Jul 19 14:00:52 chm-volumio volumio[930]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 19 14:00:53 chm-volumio volumio[930]: info: Getting Spotify volume Jul 19 14:00:53 chm-volumio volumio[930]: (node:930) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:53 chm-volumio volumio[930]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 19 14:00:53 chm-volumio volumio[930]: (node:930) 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: 139) Jul 19 14:00:53 chm-volumio volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:53 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:00:53 chm-volumio volumio[930]: info: [yt-cast-receiver] Player.setVolume(): Jul 19 14:00:53 chm-volumio volumio[930]: { level: 35, muted: false } Jul 19 14:00:53 chm-volumio volumio[930]: info: [yt-cast-receiver] Player.resume() Jul 19 14:00:53 chm-volumio volumio[930]: info: [yt-cast-receiver] Player.play(): NTpbbQUBbuo @ 0s Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::volumioStop Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreStateMachine::stop Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreStateMachine::serviceStop Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::serviceStop Jul 19 14:00:53 chm-volumio volumio[930]: info: Airplay Stop Jul 19 14:00:53 chm-volumio volumio[930]: info: Stopping Airplay Playback and sending pause command to client via USR2 Jul 19 14:00:53 chm-volumio sudo[7599]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/kill -USR2 6750 Jul 19 14:00:53 chm-volumio sudo[7599]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:00:53 chm-volumio sudo[7599]: pam_unix(sudo:session): session closed for user root Jul 19 14:00:53 chm-volumio volumio[930]: info: Shairport-Sync paused with USR2 Jul 19 14:00:53 chm-volumio volumio[930]: verbose: UNSET VOLATILE: Service: airplay_emulation Jul 19 14:00:53 chm-volumio volumio[930]: info: Stopping Airplay Playback and sending pause command to client via USR2 Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:53 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::servicePushState Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:00:53 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:00:53 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::servicePushState Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:00:53 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:00:53 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:00:53 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:53 chm-volumio sudo[7603]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/kill -USR2 6750 Jul 19 14:00:53 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:00:53 chm-volumio sudo[7603]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:00:53 chm-volumio sudo[7603]: pam_unix(sudo:session): session closed for user root Jul 19 14:00:53 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:53 chm-volumio volumio[930]: info: Shairport-Sync paused with USR2 Jul 19 14:00:53 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:53 chm-volumio volumio[930]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.9So0Mfly6laLb955MxBNU0BGG8f1.ecde7019fddfdb172fe764f17f44c868.state.track' Jul 19 14:00:53 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:00:53 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:53 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 206. Jul 19 14:00:53 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:53 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:53 chm-volumio go-librespot[7605]: Librespot-go daemon starting... Jul 19 14:00:53 chm-volumio go-librespot[7605]: time="2024-07-19T14:00:53+03:00" level=info msg="generated new device id: 51989cdb565b646222a5cbd80fce33c64452203c" Jul 19 14:00:53 chm-volumio go-librespot[7605]: time="2024-07-19T14:00:53+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:54 chm-volumio go-librespot[7605]: time="2024-07-19T14:00:54+03:00" level=debug msg="obtained new client token: AABrDj3Fo8t4FdGeZDm53nQiaiYTJ2yfe8IymYWZedijUqjpUH2wj9KxWYP13BkTyiXbdEJSdMKPp2ZFVBF4f6Rn2NQLSJuTVyuDTVVGIFQuqSqiwOiExaC0qg84sG1XwU+OlJTmcIAVl8pDYnDyLKtnMxUzW0r2QJWa0i/0xsHPXb5UFFPNNZdyxpljZmf5JQgbGUJAmVoEHYXLK2Yps1I7600Si1Xbk7opNWlIWilrAX1GXwk5TVTdrsqF" Jul 19 14:00:54 chm-volumio go-librespot[7605]: time="2024-07-19T14:00:54+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:00:54 chm-volumio go-librespot[7605]: time="2024-07-19T14:00:54+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:54 chm-volumio volumio[930]: info: Restarting Shairport-Sync after stop Jul 19 14:00:54 chm-volumio sudo[7614]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 19 14:00:54 chm-volumio sudo[7614]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:00:54 chm-volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 19 14:00:54 chm-volumio shairport-sync[6750]: {"time":1721386667107,"response":"stopAirplayPlayback Success"} Jul 19 14:00:54 chm-volumio systemd[1]: shairport-sync.service: Succeeded. Jul 19 14:00:54 chm-volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 19 14:00:54 chm-volumio volumio[930]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 19 14:00:54 chm-volumio volumio[930]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jul 19 14:00:54 chm-volumio volumio[930]: info: Restarting Shairport-Sync after stop Jul 19 14:00:54 chm-volumio sudo[7618]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 19 14:00:54 chm-volumio sudo[7618]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:00:54 chm-volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 19 14:00:54 chm-volumio sudo[7614]: pam_unix(sudo:session): session closed for user root Jul 19 14:00:54 chm-volumio volumio[930]: info: Shairport-Sync retarted Jul 19 14:00:54 chm-volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 19 14:00:54 chm-volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jul 19 14:00:54 chm-volumio systemd[1]: shairport-sync.service: Succeeded. Jul 19 14:00:54 chm-volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 19 14:00:54 chm-volumio volumio[930]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 19 14:00:54 chm-volumio volumio[930]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jul 19 14:00:54 chm-volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 19 14:00:54 chm-volumio sudo[7618]: pam_unix(sudo:session): session closed for user root Jul 19 14:00:54 chm-volumio volumio[930]: info: Shairport-Sync retarted Jul 19 14:00:54 chm-volumio go-librespot[7605]: time="2024-07-19T14:00:54+03:00" level=debug msg="completed challenge" Jul 19 14:00:55 chm-volumio volumio[930]: error: [ytcr] Error in VideoLoader.getInfo(NTpbbQUBbuo): Jul 19 14:00:55 chm-volumio volumio[930]: (SyntaxError) Unexpected token (1:47) Jul 19 14:00:55 chm-volumio volumio[930]: SyntaxError: Unexpected token (1:47) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$4.raise (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:3460:15) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$9.unexpected (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:761:10) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$9.semicolon (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:738:68) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$8.parseVarStatement (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:1169:10) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$8.parseStatement (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:916:19) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$8.parseBlock (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:1237:23) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$5.parseFunctionBody (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:3286:24) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$8.parseFunction (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:1359:10) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$8.parseFunctionStatement (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:1059:17) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$8.parseStatement (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:904:19) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.pp$8.parseTopLevel (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:818:23) Jul 19 14:00:55 chm-volumio volumio[930]: at Parser.parse (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:590:17) Jul 19 14:00:55 chm-volumio volumio[930]: at Function.parse (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:640:37) Jul 19 14:00:55 chm-volumio volumio[930]: at parse (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:5567:19) Jul 19 14:00:55 chm-volumio volumio[930]: at new Jinter (/data/plugins/music_service/ytcr/node_modules/jintr/bundle/jinter.cjs:1029:44) Jul 19 14:00:55 chm-volumio volumio[930]: at Object.evaluate [as eval] (/data/plugins/music_service/ytcr/node_modules/volumio-youtubei.js/bundle/node.cjs:21633:19) Jul 19 14:00:55 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:55 chm-volumio volumio[930]: info: CoreCommandRouter::servicePushState Jul 19 14:00:55 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:00:55 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:00:55 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:00:55 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:00:55 chm-volumio volumio[930]: info: Ignoring MPD Status Update Jul 19 14:00:55 chm-volumio volumio[930]: info: Ignoring MPD Status Update Jul 19 14:00:55 chm-volumio volumio[930]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.9So0Mfly6laLb955MxBNU0BGG8f1.ecde7019fddfdb172fe764f17f44c868.state.track' Jul 19 14:00:55 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:00:55 chm-volumio go-librespot[7605]: time="2024-07-19T14:00:55+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:55 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:55 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:56 chm-volumio volumio[930]: info: [yt-cast-receiver] Player.play(): NTpbbQUBbuo @ 0s Jul 19 14:00:56 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:56 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:56 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:56 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:57 chm-volumio volumio[930]: info: Executing endpoint metavolumio Jul 19 14:00:57 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 19 14:00:57 chm-volumio volumio[930]: error: [ytcr] Error in VideoLoader.getInfo(NTpbbQUBbuo): Jul 19 14:00:57 chm-volumio volumio[930]: (SyntaxError) Unexpected token (1:47) Jul 19 14:00:57 chm-volumio volumio[930]: SyntaxError: Unexpected token (1:47) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$4.raise (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:3460:15) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$9.unexpected (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:761:10) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$9.semicolon (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:738:68) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$8.parseVarStatement (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:1169:10) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$8.parseStatement (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:916:19) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$8.parseBlock (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:1237:23) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$5.parseFunctionBody (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:3286:24) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$8.parseFunction (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:1359:10) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$8.parseFunctionStatement (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:1059:17) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$8.parseStatement (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:904:19) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.pp$8.parseTopLevel (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:818:23) Jul 19 14:00:57 chm-volumio volumio[930]: at Parser.parse (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:590:17) Jul 19 14:00:57 chm-volumio volumio[930]: at Function.parse (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:640:37) Jul 19 14:00:57 chm-volumio volumio[930]: at parse (/data/plugins/music_service/ytcr/node_modules/acorn/dist/acorn.js:5567:19) Jul 19 14:00:57 chm-volumio volumio[930]: at new Jinter (/data/plugins/music_service/ytcr/node_modules/jintr/bundle/jinter.cjs:1029:44) Jul 19 14:00:57 chm-volumio volumio[930]: at Object.evaluate [as eval] (/data/plugins/music_service/ytcr/node_modules/volumio-youtubei.js/bundle/node.cjs:21633:19) Jul 19 14:00:57 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:00:57 chm-volumio volumio[930]: info: CoreCommandRouter::servicePushState Jul 19 14:00:57 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:00:57 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:00:57 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:00:57 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:00:57 chm-volumio volumio[930]: info: Ignoring MPD Status Update Jul 19 14:00:57 chm-volumio volumio[930]: info: Ignoring MPD Status Update Jul 19 14:00:57 chm-volumio volumio[930]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.9So0Mfly6laLb955MxBNU0BGG8f1.ecde7019fddfdb172fe764f17f44c868.state.track' Jul 19 14:00:57 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:00:58 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:00:58 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 207. Jul 19 14:00:58 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:00:58 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:00:58 chm-volumio go-librespot[7626]: Librespot-go daemon starting... Jul 19 14:00:58 chm-volumio go-librespot[7626]: time="2024-07-19T14:00:58+03:00" level=info msg="generated new device id: 1a393799eb0d299f781aac1a436d4c79a8ab967d" Jul 19 14:00:58 chm-volumio go-librespot[7626]: time="2024-07-19T14:00:58+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:00:58 chm-volumio go-librespot[7626]: time="2024-07-19T14:00:58+03:00" level=debug msg="obtained new client token: AAD7qky3j51R6h6rpno+8fKWE1zk5ywde9W3oBq1P5XxK5Dd7d6Acz+1U0AgowR9vkyMLxcN0eDZb+fNASHy82DE3ZO5zwPDLMawUmrmbjTwqvfnVco+5JR0UdWr6PPuKPhWE/a7at3UI2A3rUGrzDso4HDaWoqZR4kxK3/HB/RSSJ2y6PIkTk3gijNGX8tEqljvaodIwCId48EEdPRT/lmrkEQc0CIPhvnA63kPr6Tyo39u1Gi0H8baCUerZ6k=" Jul 19 14:00:58 chm-volumio go-librespot[7626]: time="2024-07-19T14:00:58+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:00:58 chm-volumio go-librespot[7626]: time="2024-07-19T14:00:58+03:00" level=debug msg="completed keyexchange" Jul 19 14:00:59 chm-volumio go-librespot[7626]: time="2024-07-19T14:00:59+03:00" level=debug msg="completed challenge" Jul 19 14:00:59 chm-volumio go-librespot[7626]: time="2024-07-19T14:00:59+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:00:59 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:00:59 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:00:59 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:00:59 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:00:59 chm-volumio volumio[930]: info: Executing endpoint metavolumio Jul 19 14:00:59 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 19 14:01:02 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: multiroom , enableAudioOutput Jul 19 14:01:02 chm-volumio volumio[930]: info: MRS: Starting cast device: DESKTOP-5FKU0RO Jul 19 14:01:02 chm-volumio volumio[930]: info: Enabled audio output: DESKTOP-5FKU0RO Jul 19 14:01:02 chm-volumio volumio[930]: info: MRS: Setting this device as Streaming Server Jul 19 14:01:02 chm-volumio volumio[930]: info: Jul 19 14:01:02 chm-volumio volumio[930]: [1721386862190] ---------------------------- MRS: Setting Streaming Server Jul 19 14:01:02 chm-volumio volumio[930]: info: MRS: enable multiroom server output Jul 19 14:01:02 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioMultiRoom Jul 19 14:01:02 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioMultiRoom Jul 19 14:01:02 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Jul 19 14:01:02 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioLocalPlayback Jul 19 14:01:02 chm-volumio volumio[930]: info: MRS: STARTING volumioStreaming Jul 19 14:01:02 chm-volumio sudo[7638]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:02 chm-volumio sudo[7638]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:02 chm-volumio sudo[7638]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:02 chm-volumio sudo[7641]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Jul 19 14:01:02 chm-volumio sudo[7641]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:02 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:02 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 208. Jul 19 14:01:02 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:02 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:02 chm-volumio go-librespot[7643]: Librespot-go daemon starting... Jul 19 14:01:02 chm-volumio systemd[1]: Started VolumioStreamingService. Jul 19 14:01:02 chm-volumio go-librespot[7643]: time="2024-07-19T14:01:02+03:00" level=info msg="generated new device id: 207e6506f1548ff463cde06570f2b58088d88ff5" Jul 19 14:01:02 chm-volumio go-librespot[7643]: time="2024-07-19T14:01:02+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:02 chm-volumio sudo[7641]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:02 chm-volumio sudo[7650]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:02 chm-volumio sudo[7650]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:02 chm-volumio volumio[930]: info: MRS: volumioStreaming STARTED Jul 19 14:01:02 chm-volumio sudo[7650]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:02 chm-volumio go-librespot[7643]: time="2024-07-19T14:01:02+03:00" level=debug msg="obtained new client token: AABgo2Nobgn0zK9gJB+LKEyCyZh70+WBoKSlURIGaneNaY4gbwfUIxMidd+eD3GxzW6VFwqE+7oM5XZImb9aqiU1ibLMybUrMjAqlHlobNuCGTY1khI/V66VrADxH7TEnP+ENl94MBqi3kLkR9MB28dFfbp4VfjK0W4ccQCM1U8d0J7qz6vGzzqSQA8Qpo4mY1ouRWOYXtm1835QFRLSJ7mfsYJ3FEBMBQx5afSXTP1cLR8s3jv+ZxT8DMnMG6I=" Jul 19 14:01:02 chm-volumio go-librespot[7643]: time="2024-07-19T14:01:02+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:02 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:02 chm-volumio go-librespot[7643]: time="2024-07-19T14:01:02+03:00" level=debug msg="new websocket client" Jul 19 14:01:02 chm-volumio volumio[930]: info: Connection to go-librespot Websocket established Jul 19 14:01:02 chm-volumio go-librespot[7643]: time="2024-07-19T14:01:02+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:03 chm-volumio go-librespot[7643]: time="2024-07-19T14:01:03+03:00" level=debug msg="completed challenge" Jul 19 14:01:03 chm-volumio go-librespot[7643]: time="2024-07-19T14:01:03+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:03 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:03 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:03 chm-volumio volumio[930]: info: Connection to go-librespot Websocket closed Jul 19 14:01:03 chm-volumio volumio[930]: error: Failed request for metavolumio API Jul 19 14:01:04 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: multiroom , disableAudioOutput Jul 19 14:01:04 chm-volumio volumio[930]: info: MRS: Setting this device as single Jul 19 14:01:04 chm-volumio volumio[930]: info: Jul 19 14:01:04 chm-volumio volumio[930]: [1721386864205] ---------------------------- Setting Multiroom Single Jul 19 14:01:04 chm-volumio volumio[930]: info: MRS: disable multiroom output Jul 19 14:01:04 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioDiscard Jul 19 14:01:04 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioDiscard Jul 19 14:01:04 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Jul 19 14:01:04 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioLocalPlayback Jul 19 14:01:05 chm-volumio volumio[930]: info: MRS: STOPPING volumioStreaming Jul 19 14:01:05 chm-volumio sudo[7658]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Jul 19 14:01:05 chm-volumio sudo[7658]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:05 chm-volumio sudo[7661]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:05 chm-volumio systemd[1]: Stopping VolumioStreamingService... Jul 19 14:01:05 chm-volumio systemd[1]: volumioStreaming.service: Main process exited, code=killed, status=15/TERM Jul 19 14:01:05 chm-volumio sudo[7661]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:05 chm-volumio volumio[930]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 19 14:01:05 chm-volumio sudo[7661]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:05 chm-volumio volumio[930]: info: MRS: Removed streaming files Jul 19 14:01:05 chm-volumio systemd[1]: volumioStreaming.service: Succeeded. Jul 19 14:01:05 chm-volumio systemd[1]: Stopped VolumioStreamingService. Jul 19 14:01:05 chm-volumio sudo[7658]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:05 chm-volumio volumio[930]: info: MRS: volumioStreaming STOPPED Jul 19 14:01:05 chm-volumio volumio[930]: info: Getting Spotify volume Jul 19 14:01:05 chm-volumio volumio[930]: (node:930) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:05 chm-volumio volumio[930]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 19 14:01:05 chm-volumio volumio[930]: (node:930) 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: 140) Jul 19 14:01:05 chm-volumio volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:01:05 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:05 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:06 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:06 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:06 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:06 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 209. Jul 19 14:01:06 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:06 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:06 chm-volumio go-librespot[7664]: Librespot-go daemon starting... Jul 19 14:01:06 chm-volumio go-librespot[7664]: time="2024-07-19T14:01:06+03:00" level=info msg="generated new device id: 2949b3f99680ae7ca1e8f14f6c261b9f7efb5a52" Jul 19 14:01:06 chm-volumio go-librespot[7664]: time="2024-07-19T14:01:06+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:06 chm-volumio go-librespot[7664]: time="2024-07-19T14:01:06+03:00" level=debug msg="obtained new client token: AAAt2Mz+tD/LRm1VTFPJMK2L4XqnBel4zIUSfULFT0hV8JL3auSJwJsNABO41bH0oZfOaZrze48HRS/qEALxvVV2q7Gara/gEV8sQLP3dmeQlTLwCZS/F4qMIu7NK1BrOQVkN7ZTYZ/mshVz4BJrRZZxXdzZdX2015GAqeqCm3ctaYJxhfG4SclHdzDO9oBIaJ+qp9ma3EoZcjb3rYy77foMMrdVwji0Ai6HTRdcJxOF8P6o9QS1RSP20I/qb0g=" Jul 19 14:01:07 chm-volumio go-librespot[7664]: time="2024-07-19T14:01:07+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:07 chm-volumio go-librespot[7664]: time="2024-07-19T14:01:07+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:07 chm-volumio go-librespot[7664]: time="2024-07-19T14:01:07+03:00" level=debug msg="completed challenge" Jul 19 14:01:07 chm-volumio go-librespot[7664]: time="2024-07-19T14:01:07+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:07 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:07 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:08 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: multiroom , enableAudioOutput Jul 19 14:01:08 chm-volumio volumio[930]: info: MRS: Starting browser stream Jul 19 14:01:08 chm-volumio volumio[930]: info: MRS: Setting this device as Streaming Server Jul 19 14:01:08 chm-volumio volumio[930]: info: Jul 19 14:01:08 chm-volumio volumio[930]: [1721386868503] ---------------------------- MRS: Setting Streaming Server Jul 19 14:01:08 chm-volumio volumio[930]: info: Enabled audio output: browserPlayback Jul 19 14:01:08 chm-volumio volumio[930]: info: MRS: enable multiroom server output Jul 19 14:01:08 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioMultiRoom Jul 19 14:01:08 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioMultiRoom Jul 19 14:01:08 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Jul 19 14:01:08 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioLocalPlayback Jul 19 14:01:08 chm-volumio volumio[930]: info: MRS: STARTING volumioStreaming Jul 19 14:01:08 chm-volumio sudo[7676]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:08 chm-volumio sudo[7676]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:08 chm-volumio sudo[7676]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:08 chm-volumio sudo[7679]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Jul 19 14:01:08 chm-volumio sudo[7679]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:08 chm-volumio systemd[1]: Started VolumioStreamingService. Jul 19 14:01:08 chm-volumio sudo[7679]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:08 chm-volumio volumio[930]: info: MRS: volumioStreaming STARTED Jul 19 14:01:08 chm-volumio sudo[7682]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:08 chm-volumio sudo[7682]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:08 chm-volumio sudo[7682]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:09 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:09 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:10 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:10 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 210. Jul 19 14:01:10 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:10 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:10 chm-volumio go-librespot[7686]: Librespot-go daemon starting... Jul 19 14:01:10 chm-volumio go-librespot[7686]: time="2024-07-19T14:01:10+03:00" level=info msg="generated new device id: 8af9506101199957c3e0d097e0a374a4527d6eab" Jul 19 14:01:10 chm-volumio go-librespot[7686]: time="2024-07-19T14:01:10+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:11 chm-volumio go-librespot[7686]: time="2024-07-19T14:01:11+03:00" level=debug msg="obtained new client token: AAD8CWMH6mPiiKwS5RK6jHSHmvohT1JDzImUpdGlLkiygysk3lz/jdtlc6RIF/7ItSlK4iDuY4btM8usNfR3gRJnwQ7RDTsKTyGmyQ8oF6Zt+cIovcs9grJBhKN+ZIO+nOXHL/slhWTL+KkgkNlVO4/+8/kAGV3BWmgnnczetaMC9U/sCvuklAMT8pz+GK5mNOF2zddBfxhfLVAdMyUvNNElAMB2brq132Qf0nTldnrFsuuppgeQsuy4tNI/" Jul 19 14:01:11 chm-volumio go-librespot[7686]: time="2024-07-19T14:01:11+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 19 14:01:11 chm-volumio go-librespot[7686]: time="2024-07-19T14:01:11+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:11 chm-volumio go-librespot[7686]: time="2024-07-19T14:01:11+03:00" level=debug msg="completed challenge" Jul 19 14:01:12 chm-volumio go-librespot[7686]: time="2024-07-19T14:01:12+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:12 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:12 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:12 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:12 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: multiroom , disableAudioOutput Jul 19 14:01:14 chm-volumio volumio[930]: info: MRS: Starting browser stream Jul 19 14:01:14 chm-volumio volumio[930]: info: MRS: Setting this device as single Jul 19 14:01:14 chm-volumio volumio[930]: info: Jul 19 14:01:14 chm-volumio volumio[930]: [1721386874135] ---------------------------- Setting Multiroom Single Jul 19 14:01:14 chm-volumio volumio[930]: info: MRS: disable multiroom output Jul 19 14:01:14 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioDiscard Jul 19 14:01:14 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioDiscard Jul 19 14:01:14 chm-volumio volumio[930]: verbose: New Socket.io Connection to 192.168.10.18 from 192.168.10.29 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/126.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:14 chm-volumio volumio[930]: info: Received Get System Info Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 19 14:01:14 chm-volumio volumio[930]: info: Discovery: Getting this device information Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetVisibleSources Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 19 14:01:14 chm-volumio volumio[930]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jul 19 14:01:14 chm-volumio volumio[930]: info: Received Get System Info Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 19 14:01:14 chm-volumio volumio[930]: info: Discovery: Getting this device information Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:14 chm-volumio volumio[930]: info: Listing playlists Jul 19 14:01:14 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jul 19 14:01:14 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Jul 19 14:01:14 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioLocalPlayback Jul 19 14:01:15 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:15 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 211. Jul 19 14:01:15 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:15 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:15 chm-volumio go-librespot[7696]: Librespot-go daemon starting... Jul 19 14:01:15 chm-volumio go-librespot[7696]: time="2024-07-19T14:01:15+03:00" level=info msg="generated new device id: d9e16ace281d3d279d98dff159f0d1b3d08712b5" Jul 19 14:01:15 chm-volumio go-librespot[7696]: time="2024-07-19T14:01:15+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:15 chm-volumio go-librespot[7696]: time="2024-07-19T14:01:15+03:00" level=debug msg="obtained new client token: AAB1CyB++IXR5wjOVLvNtWEv0Z91QJnfHUBJhioKRHYfp6hGCdCUZIswlO6LA2GGZsK1sk/DPz9S8xiLWSYOo6UYI3G2nlc/jQ6Up1p8vFEkzbMZ4d4T8Y2ImwQLweM/6qWZ8Yi5AIHKMVuz20yvMKLe+b9tvs0eBj6rqUUvFXaeojhkEtnsyafU+Np6yQrhO4VS+J4q0lMBp02ahn977BOTHLBnrHT3UVgcoNOWUTmJgOg6bAsYp58tQOu04ss=" Jul 19 14:01:15 chm-volumio go-librespot[7696]: time="2024-07-19T14:01:15+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:15 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:15 chm-volumio volumio[930]: info: Connection to go-librespot Websocket established Jul 19 14:01:15 chm-volumio go-librespot[7696]: time="2024-07-19T14:01:15+03:00" level=debug msg="new websocket client" Jul 19 14:01:15 chm-volumio volumio[930]: info: MRS: STOPPING volumioStreaming Jul 19 14:01:15 chm-volumio sudo[7705]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Jul 19 14:01:15 chm-volumio sudo[7705]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:15 chm-volumio systemd[1]: Stopping VolumioStreamingService... Jul 19 14:01:15 chm-volumio systemd[1]: volumioStreaming.service: Main process exited, code=killed, status=15/TERM Jul 19 14:01:15 chm-volumio volumio[930]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 19 14:01:15 chm-volumio go-librespot[7696]: time="2024-07-19T14:01:15+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:15 chm-volumio systemd[1]: volumioStreaming.service: Succeeded. Jul 19 14:01:15 chm-volumio systemd[1]: Stopped VolumioStreamingService. Jul 19 14:01:15 chm-volumio sudo[7705]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:15 chm-volumio volumio[930]: info: MRS: volumioStreaming STOPPED Jul 19 14:01:15 chm-volumio sudo[7708]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:15 chm-volumio sudo[7708]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:15 chm-volumio sudo[7708]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:15 chm-volumio volumio[930]: info: MRS: Removed streaming files Jul 19 14:01:16 chm-volumio go-librespot[7696]: time="2024-07-19T14:01:16+03:00" level=debug msg="completed challenge" Jul 19 14:01:16 chm-volumio go-librespot[7696]: time="2024-07-19T14:01:16+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:16 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:16 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:16 chm-volumio volumio[930]: info: Connection to go-librespot Websocket closed Jul 19 14:01:16 chm-volumio volumio[930]: info: Executing endpoint metavolumio Jul 19 14:01:16 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 19 14:01:17 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: multiroom , enableAudioOutput Jul 19 14:01:17 chm-volumio volumio[930]: info: MRS: Starting cast device: DESKTOP-5FKU0RO Jul 19 14:01:17 chm-volumio volumio[930]: info: Enabled audio output: DESKTOP-5FKU0RO Jul 19 14:01:17 chm-volumio volumio[930]: info: MRS: Setting this device as Streaming Server Jul 19 14:01:17 chm-volumio volumio[930]: info: Jul 19 14:01:17 chm-volumio volumio[930]: [1721386877738] ---------------------------- MRS: Setting Streaming Server Jul 19 14:01:17 chm-volumio volumio[930]: info: MRS: enable multiroom server output Jul 19 14:01:17 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioMultiRoom Jul 19 14:01:17 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioMultiRoom Jul 19 14:01:17 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Jul 19 14:01:17 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioLocalPlayback Jul 19 14:01:17 chm-volumio volumio[930]: info: MRS: STARTING volumioStreaming Jul 19 14:01:17 chm-volumio sudo[7713]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:17 chm-volumio sudo[7713]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:17 chm-volumio sudo[7713]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:17 chm-volumio sudo[7716]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Jul 19 14:01:17 chm-volumio sudo[7716]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:17 chm-volumio systemd[1]: Started VolumioStreamingService. Jul 19 14:01:17 chm-volumio sudo[7716]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:17 chm-volumio volumio[930]: info: MRS: volumioStreaming STARTED Jul 19 14:01:17 chm-volumio sudo[7719]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:17 chm-volumio sudo[7719]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:17 chm-volumio sudo[7719]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:18 chm-volumio volumio[930]: info: Getting Spotify volume Jul 19 14:01:18 chm-volumio volumio[930]: (node:930) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:18 chm-volumio volumio[930]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 19 14:01:18 chm-volumio volumio[930]: (node:930) 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: 141) Jul 19 14:01:18 chm-volumio volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:01:18 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:18 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:19 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:19 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:19 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:19 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 212. Jul 19 14:01:19 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:19 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:19 chm-volumio go-librespot[7722]: Librespot-go daemon starting... Jul 19 14:01:19 chm-volumio go-librespot[7722]: time="2024-07-19T14:01:19+03:00" level=info msg="generated new device id: 541dcf1384c5349974ef26c1a59220f924aa7b54" Jul 19 14:01:19 chm-volumio go-librespot[7722]: time="2024-07-19T14:01:19+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:19 chm-volumio go-librespot[7722]: time="2024-07-19T14:01:19+03:00" level=debug msg="obtained new client token: AADdzSqQIhedutIBpQH1xIGEWF6PFGjGOScZxGi4aCHrQ9KqFPjocHjl3D+DgS4nxFCDD0/2cS6yVn/WjDSFu0iTa6RWASa2aLuTyR2ucyLIIqB+2QwVcCiznkDncjWQn2wMYqALgIIvwTkuHY+NQpMPKbdW1q+MWF0vIWQo0NCmDCTrzLtQ3rX/WjVPc4LPKcwQW+taQgVTXdJrbkMQC4MiMyM+huDQHhxduJsK9/hi26O4pCufFARIKTdSTJA=" Jul 19 14:01:19 chm-volumio go-librespot[7722]: time="2024-07-19T14:01:19+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:19 chm-volumio go-librespot[7722]: time="2024-07-19T14:01:19+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:20 chm-volumio go-librespot[7722]: time="2024-07-19T14:01:20+03:00" level=debug msg="completed challenge" Jul 19 14:01:20 chm-volumio go-librespot[7722]: time="2024-07-19T14:01:20+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:20 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:20 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:21 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetQueue Jul 19 14:01:21 chm-volumio volumio[930]: info: CoreStateMachine::getQueue Jul 19 14:01:21 chm-volumio volumio[930]: info: CorePlayQueue::getQueue Jul 19 14:01:22 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jul 19 14:01:22 chm-volumio volumio[930]: info: Preload queue cleared Jul 19 14:01:22 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:22 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:23 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:23 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 213. Jul 19 14:01:23 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:23 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:23 chm-volumio go-librespot[7732]: Librespot-go daemon starting... Jul 19 14:01:23 chm-volumio go-librespot[7732]: time="2024-07-19T14:01:23+03:00" level=info msg="generated new device id: 6d4ccfa2f4c696adb1dbfa99ef78cb387432dc3c" Jul 19 14:01:23 chm-volumio go-librespot[7732]: time="2024-07-19T14:01:23+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:23 chm-volumio go-librespot[7732]: time="2024-07-19T14:01:23+03:00" level=debug msg="obtained new client token: AAA9Bd1zdFozc45swIHzH4EMq6GDnZDUQ6VYZ10bd5HfnFF+2FupSqqB2jWq7TriaKHBn21oXvr0SeR3r5/qflaf+xEeQViUH7Ex4a7uBWJtWmdz3OQkHzuSyV9iqLna8yQMccQ0TzJ9Dal0Q17/QZJfPbIe1DyJZkroBSRABCx0gXqdOKw35i1OaUnUdaqZWpgj4dkHyE44TXZ/m171x9JxdDqI9EJfnAzq94X3F5kDrotxy7jfdNi6AZ5V+tE=" Jul 19 14:01:24 chm-volumio go-librespot[7732]: time="2024-07-19T14:01:24+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:24 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jul 19 14:01:24 chm-volumio go-librespot[7732]: time="2024-07-19T14:01:24+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:24 chm-volumio go-librespot[7732]: time="2024-07-19T14:01:24+03:00" level=debug msg="completed challenge" Jul 19 14:01:24 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jul 19 14:01:24 chm-volumio volumio[930]: info: TuneIn handleBrowseUri: tunein/location Jul 19 14:01:24 chm-volumio go-librespot[7732]: time="2024-07-19T14:01:24+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:24 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:24 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:25 chm-volumio volumio[930]: info: Preload queue cleared Jul 19 14:01:25 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:25 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:25 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jul 19 14:01:25 chm-volumio volumio[930]: info: TuneIn handleBrowseUri: tunein/browse/?id=r101216 Jul 19 14:01:25 chm-volumio volumio[930]: info: [TuneIn] Fetching (browse) results For tunein/browse/?id=r101216 Jul 19 14:01:26 chm-volumio volumio[930]: info: Preload queue cleared Jul 19 14:01:26 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jul 19 14:01:26 chm-volumio volumio[930]: info: TuneIn handleBrowseUri: tunein/browse/?id=r100313 Jul 19 14:01:26 chm-volumio volumio[930]: info: [TuneIn] Fetching (browse) results For tunein/browse/?id=r100313 Jul 19 14:01:26 chm-volumio volumio[930]: info: Preload queue cleared Jul 19 14:01:26 chm-volumio volumio[930]: info: Preload queue cleared Jul 19 14:01:27 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:27 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 214. Jul 19 14:01:27 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:27 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:27 chm-volumio go-librespot[7740]: Librespot-go daemon starting... Jul 19 14:01:27 chm-volumio go-librespot[7740]: time="2024-07-19T14:01:27+03:00" level=info msg="generated new device id: bc96f80247f007c5e60efabd7a9bc22698b49699" Jul 19 14:01:27 chm-volumio go-librespot[7740]: time="2024-07-19T14:01:27+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:28 chm-volumio go-librespot[7740]: time="2024-07-19T14:01:28+03:00" level=debug msg="obtained new client token: AABLJpqjrcO+LaSjJSjk/D1VtwrwaaiSJYRmzsc8HvV77pgeu5414O8r5+FoUBuONmgkvYhnZysk7m7Sxnbyl33Ow8zHKi/NyPV+KhOhxKKwL79ouK6FcuLW5zf6vbz2Aecso+6MLNblcyusXKqw26FzdGsmmgLjuP3WrwRph8ytIlpmoeFfCclDxQOxOyVI3X0bQ4UPcB+wnnJMCyuueFJ6vIDY8P64MdixvHji28pxM/wbZLvbWB4RDJuI" Jul 19 14:01:28 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:28 chm-volumio volumio[930]: info: Connection to go-librespot Websocket established Jul 19 14:01:28 chm-volumio go-librespot[7740]: time="2024-07-19T14:01:28+03:00" level=debug msg="new websocket client" Jul 19 14:01:28 chm-volumio go-librespot[7740]: time="2024-07-19T14:01:28+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:28 chm-volumio go-librespot[7740]: time="2024-07-19T14:01:28+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:28 chm-volumio go-librespot[7740]: time="2024-07-19T14:01:28+03:00" level=debug msg="completed challenge" Jul 19 14:01:29 chm-volumio go-librespot[7740]: time="2024-07-19T14:01:29+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:29 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:29 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:29 chm-volumio volumio[930]: info: Connection to go-librespot Websocket closed Jul 19 14:01:29 chm-volumio ntpd[753]: Soliciting pool server 2a0c:5cc0:1:1::387e:6a4 Jul 19 14:01:30 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jul 19 14:01:30 chm-volumio volumio[930]: info: TuneIn handleBrowseUri: tunein/local Jul 19 14:01:30 chm-volumio volumio[930]: info: Preload queue cleared Jul 19 14:01:31 chm-volumio volumio[930]: info: Getting Spotify volume Jul 19 14:01:31 chm-volumio volumio[930]: (node:930) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:31 chm-volumio volumio[930]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 19 14:01:31 chm-volumio volumio[930]: (node:930) 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: 142) Jul 19 14:01:31 chm-volumio volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:31 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:31 chm-volumio volumio[930]: info: Preload queue cleared Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::ClearQueue Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::stop Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::serviceStop Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::serviceStop Jul 19 14:01:31 chm-volumio volumio[930]: info: CorePlayQueue::clearPlayQueue Jul 19 14:01:31 chm-volumio volumio[930]: info: CorePlayQueue::saveQueue Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushQueue Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::addQueueItems Jul 19 14:01:31 chm-volumio volumio[930]: info: CorePlayQueue::addQueueItems Jul 19 14:01:31 chm-volumio volumio[930]: info: Preload queue cleared Jul 19 14:01:31 chm-volumio volumio[930]: info: Adding Item to queue: http://opml.radiotime.com/Tune.ashx?id=s5991 Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushQueue Jul 19 14:01:31 chm-volumio volumio[930]: info: CorePlayQueue::saveQueue Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::updateTrackBlock Jul 19 14:01:31 chm-volumio volumio[930]: info: CorePlayQueue::getTrackBlock Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPlay Jul 19 14:01:31 chm-volumio volumio[930]: verbose: UNSET VOLATILE: Service: ytcr Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::servicePushState Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:31 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:31 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::servicePushState Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:31 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:31 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::play index 0 Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::stop Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::updateTrackBlock Jul 19 14:01:31 chm-volumio volumio[930]: info: CorePlayQueue::getTrackBlock Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::stPlaybackTimer Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:31 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:31 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:31 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::serviceStop Jul 19 14:01:31 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::serviceStop Jul 19 14:01:31 chm-volumio volumio[930]: info: [1721386891828] ControllerWebradio::stop Jul 19 14:01:31 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand stop Jul 19 14:01:31 chm-volumio volumio[930]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.9So0Mfly6laLb955MxBNU0BGG8f1.ecde7019fddfdb172fe764f17f44c868.state.track' Jul 19 14:01:31 chm-volumio volumio[930]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.9So0Mfly6laLb955MxBNU0BGG8f1.ecde7019fddfdb172fe764f17f44c868.state.track' Jul 19 14:01:31 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:31 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:31 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:31 chm-volumio volumio[930]: info: sendMpdCommand stop took 19 milliseconds Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::play index undefined Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 19 14:01:31 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreStateMachine::startPlaybackTimer Jul 19 14:01:31 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetVisibleSources Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 19 14:01:31 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jul 19 14:01:31 chm-volumio volumio[930]: info: [1721386891851] ControllerWebradio::clearAddPlayTrack Jul 19 14:01:31 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand stop Jul 19 14:01:31 chm-volumio volumio[930]: info: sendMpdCommand stop took 7 milliseconds Jul 19 14:01:31 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand clear Jul 19 14:01:31 chm-volumio volumio[930]: info: Jul 19 14:01:31 chm-volumio volumio[930]: ---------------------------- MPD announces system playlist update Jul 19 14:01:31 chm-volumio volumio[930]: info: Ignoring MPD Status Update Jul 19 14:01:31 chm-volumio volumio[930]: info: sendMpdCommand clear took 1 milliseconds Jul 19 14:01:31 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand load "http://r1.phileradio.com:8193/89FM" Jul 19 14:01:31 chm-volumio volumio[930]: error: updateQueue error: null Jul 19 14:01:31 chm-volumio volumio[930]: info: ------------------------------ 7ms Jul 19 14:01:32 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:32 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:32 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:32 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 215. Jul 19 14:01:32 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:32 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:32 chm-volumio go-librespot[7749]: Librespot-go daemon starting... Jul 19 14:01:32 chm-volumio go-librespot[7749]: time="2024-07-19T14:01:32+03:00" level=info msg="generated new device id: 891cf1472a08b2452cb83f67090821153f9a6cfc" Jul 19 14:01:32 chm-volumio go-librespot[7749]: time="2024-07-19T14:01:32+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:32 chm-volumio go-librespot[7749]: time="2024-07-19T14:01:32+03:00" level=debug msg="obtained new client token: AAA5m3rwWtzkfm3sn6/KjbGMHIXKa+XHZ224v4yKb7IcXk171EQ/W5B83lFQqYDGvz+WBinUusGkZ+b1LIctXRx1p9SQKYaQGcIVxH8fRKrlqcpG0xjX+CxubdfxX8fPLxJA0SYvBbaCoW+olP7krCGdrbmkvyaA/JTZq//pQUlsr6rJJvFeJJmZVyXaKF6973NskBUWDR0aDYqxF3c6Jqx7dKL2cp0PEj4hRLBm/1aorOTcbWzfWrU42tckHNs=" Jul 19 14:01:32 chm-volumio go-librespot[7749]: time="2024-07-19T14:01:32+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:32 chm-volumio go-librespot[7749]: time="2024-07-19T14:01:32+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:32 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand add "http://r1.phileradio.com:8193/89FM" Jul 19 14:01:32 chm-volumio volumio[930]: info: Jul 19 14:01:32 chm-volumio volumio[930]: ---------------------------- MPD announces system playlist update Jul 19 14:01:32 chm-volumio volumio[930]: info: Ignoring MPD Status Update Jul 19 14:01:32 chm-volumio volumio[930]: info: sendMpdCommand add "http://r1.phileradio.com:8193/89FM" took 1 milliseconds Jul 19 14:01:32 chm-volumio volumio[930]: info: CoreStateMachine::setConsumeUpdateService mpd Jul 19 14:01:32 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand play Jul 19 14:01:32 chm-volumio volumio[930]: info: ------------------------------ 4ms Jul 19 14:01:32 chm-volumio volumio[930]: info: sendMpdCommand play took 2 milliseconds Jul 19 14:01:33 chm-volumio go-librespot[7749]: time="2024-07-19T14:01:33+03:00" level=debug msg="completed challenge" Jul 19 14:01:33 chm-volumio volumio[930]: info: Jul 19 14:01:33 chm-volumio volumio[930]: ---------------------------- MPD announces state update: player Jul 19 14:01:33 chm-volumio volumio[930]: info: ControllerMpd::getState Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand status Jul 19 14:01:33 chm-volumio volumio[930]: info: Jul 19 14:01:33 chm-volumio volumio[930]: ---------------------------- MPD announces state update: player Jul 19 14:01:33 chm-volumio volumio[930]: info: sendMpdCommand status took 18 milliseconds Jul 19 14:01:33 chm-volumio volumio[930]: info: ControllerMpd::getState Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand status Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::parseState Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 19 14:01:33 chm-volumio volumio[930]: info: sendMpdCommand status took 2 milliseconds Jul 19 14:01:33 chm-volumio volumio[930]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::parseState Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::parseTrackInfo Jul 19 14:01:33 chm-volumio volumio[930]: info: ControllerMpd::pushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::servicePushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:33 chm-volumio volumio[930]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"89FM","artist":null,"album":null,"uri":"http://r1.phileradio.com:8193/89FM","trackType":""} Jul 19 14:01:33 chm-volumio volumio[930]: verbose: CURRENT POSITION 0 Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::syncState stateService play Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::syncState currentStatus stop Jul 19 14:01:33 chm-volumio volumio[930]: info: ------------------------------ 26ms Jul 19 14:01:33 chm-volumio volumio[930]: info: sendMpdCommand playlistinfo took 3 milliseconds Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::parseTrackInfo Jul 19 14:01:33 chm-volumio volumio[930]: info: ControllerMpd::pushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::servicePushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:33 chm-volumio volumio[930]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"89FM","artist":null,"album":null,"uri":"http://r1.phileradio.com:8193/89FM","trackType":""} Jul 19 14:01:33 chm-volumio volumio[930]: verbose: CURRENT POSITION 0 Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::syncState stateService play Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::syncState currentStatus play Jul 19 14:01:33 chm-volumio volumio[930]: info: Received an update from plugin. extracting info from payload Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:33 chm-volumio volumio[930]: info: ------------------------------ 24ms Jul 19 14:01:33 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:33 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:33 chm-volumio volumio[930]: info: Jul 19 14:01:33 chm-volumio volumio[930]: ---------------------------- MPD announces system playlist update Jul 19 14:01:33 chm-volumio volumio[930]: info: Ignoring MPD Status Update Jul 19 14:01:33 chm-volumio volumio[930]: info: Jul 19 14:01:33 chm-volumio volumio[930]: ---------------------------- MPD announces state update: player Jul 19 14:01:33 chm-volumio volumio[930]: info: ControllerMpd::getState Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand status Jul 19 14:01:33 chm-volumio volumio[930]: info: Jul 19 14:01:33 chm-volumio volumio[930]: ---------------------------- MPD announces system playlist update Jul 19 14:01:33 chm-volumio volumio[930]: info: Ignoring MPD Status Update Jul 19 14:01:33 chm-volumio volumio[930]: info: Jul 19 14:01:33 chm-volumio volumio[930]: ---------------------------- MPD announces state update: player Jul 19 14:01:33 chm-volumio volumio[930]: info: ControllerMpd::getState Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand status Jul 19 14:01:33 chm-volumio volumio[930]: info: ------------------------------ 5ms Jul 19 14:01:33 chm-volumio volumio[930]: info: sendMpdCommand status took 3 milliseconds Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::parseState Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 19 14:01:33 chm-volumio volumio[930]: info: ------------------------------ 5ms Jul 19 14:01:33 chm-volumio volumio[930]: info: sendMpdCommand status took 3 milliseconds Jul 19 14:01:33 chm-volumio volumio[930]: info: sendMpdCommand playlistinfo took 3 milliseconds Jul 19 14:01:33 chm-volumio go-librespot[7749]: time="2024-07-19T14:01:33+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::parseState Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::parseTrackInfo Jul 19 14:01:33 chm-volumio volumio[930]: info: ControllerMpd::pushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::servicePushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:33 chm-volumio volumio[930]: verbose: STATE SERVICE {"status":"play","position":0,"seek":979,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"89FM","artist":"Kiss FM","album":null,"uri":"http://r1.phileradio.com:8193/89FM","trackType":""} Jul 19 14:01:33 chm-volumio volumio[930]: verbose: CURRENT POSITION 0 Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::syncState stateService play Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::syncState currentStatus play Jul 19 14:01:33 chm-volumio volumio[930]: info: Received an update from plugin. extracting info from payload Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:33 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:33 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:33 chm-volumio volumio[930]: info: ------------------------------ 24ms Jul 19 14:01:33 chm-volumio volumio[930]: info: sendMpdCommand playlistinfo took 18 milliseconds Jul 19 14:01:33 chm-volumio volumio[930]: verbose: ControllerMpd::parseTrackInfo Jul 19 14:01:33 chm-volumio volumio[930]: info: ControllerMpd::pushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::servicePushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:33 chm-volumio volumio[930]: verbose: STATE SERVICE {"status":"play","position":0,"seek":979,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"89FM","artist":"Kiss FM","album":null,"uri":"http://r1.phileradio.com:8193/89FM","trackType":""} Jul 19 14:01:33 chm-volumio volumio[930]: verbose: CURRENT POSITION 0 Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::syncState stateService play Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::syncState currentStatus play Jul 19 14:01:33 chm-volumio volumio[930]: info: Received an update from plugin. extracting info from payload Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CorePlayQueue::getTrack 0 Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:33 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:33 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:33 chm-volumio volumio[930]: info: ------------------------------ 30ms Jul 19 14:01:33 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:33 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:35 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:35 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:36 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:36 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 216. Jul 19 14:01:36 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:36 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:36 chm-volumio go-librespot[7764]: Librespot-go daemon starting... Jul 19 14:01:36 chm-volumio go-librespot[7764]: time="2024-07-19T14:01:36+03:00" level=info msg="generated new device id: f9daf8f65c8982c1282a1b2495de9b305729f97f" Jul 19 14:01:36 chm-volumio go-librespot[7764]: time="2024-07-19T14:01:36+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:36 chm-volumio go-librespot[7764]: time="2024-07-19T14:01:36+03:00" level=debug msg="obtained new client token: AACwFsg8RNdRsUeNetdcAmt3BpO5D4/DQLIDKrohgXJagbBZUGZGzkUfPncm4G2hDozltf/l5Sbd5OaW3BFzUyGZTu//m+Tc5nW0kHSrPG+PZjhXc2GTprVWyELbMrm2x90OdPLZHIMS1oZjmpwfDCw3IJ/HnhYjWHjWTYe1oegM964b5ypaX9YvDpPAM6Xwfc0x1hVfNSaNpxoIU/4jT85ykRMIrV1L4WNuB/ccwbABmDJ2h6JzhqUTz3PcsyI=" Jul 19 14:01:36 chm-volumio go-librespot[7764]: time="2024-07-19T14:01:36+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:36 chm-volumio go-librespot[7764]: time="2024-07-19T14:01:36+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:37 chm-volumio go-librespot[7764]: time="2024-07-19T14:01:37+03:00" level=debug msg="completed challenge" Jul 19 14:01:37 chm-volumio go-librespot[7764]: time="2024-07-19T14:01:37+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:37 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:37 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:38 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:38 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:40 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:40 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 217. Jul 19 14:01:40 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:40 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:40 chm-volumio go-librespot[7774]: Librespot-go daemon starting... Jul 19 14:01:40 chm-volumio go-librespot[7774]: time="2024-07-19T14:01:40+03:00" level=info msg="generated new device id: 7de76d8d45f90763bba9c821e432756303c22444" Jul 19 14:01:40 chm-volumio go-librespot[7774]: time="2024-07-19T14:01:40+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:40 chm-volumio go-librespot[7774]: time="2024-07-19T14:01:40+03:00" level=debug msg="obtained new client token: AAAip9oyqYHsrTvlBgpvauh0aJyE0ya+ikWfw2uvVoMS2gKVymziBG4eCxc/V1oL1GlJuVeM9hgsUkGSuTpw+7B3HzdXlRFYNCoIOeXQz77aFoDtFgcTi3fjnrPxpBvKZrVu+As6AfQUHjK0TgAc5SNlk8hmL69Aj0xbRx23QlqFHMNC0okN8Ri5Yj3GaB9nJ1C1tfPlhbEU8zSFqbh/2iXkRa5TrNcGp4fWPHCbfyZBChCQZmfOEDtL7SYqkFo=" Jul 19 14:01:41 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:41 chm-volumio go-librespot[7774]: time="2024-07-19T14:01:41+03:00" level=debug msg="new websocket client" Jul 19 14:01:41 chm-volumio volumio[930]: info: Connection to go-librespot Websocket established Jul 19 14:01:41 chm-volumio go-librespot[7774]: time="2024-07-19T14:01:41+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:41 chm-volumio go-librespot[7774]: time="2024-07-19T14:01:41+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:41 chm-volumio go-librespot[7774]: time="2024-07-19T14:01:41+03:00" level=debug msg="completed challenge" Jul 19 14:01:41 chm-volumio go-librespot[7774]: time="2024-07-19T14:01:41+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:41 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:41 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:41 chm-volumio volumio[930]: info: Connection to go-librespot Websocket closed Jul 19 14:01:44 chm-volumio volumio[930]: info: Getting Spotify volume Jul 19 14:01:44 chm-volumio volumio[930]: (node:930) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:44 chm-volumio volumio[930]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 19 14:01:44 chm-volumio volumio[930]: (node:930) 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: 143) Jul 19 14:01:44 chm-volumio volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:01:44 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:44 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 19 14:01:44 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:44 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:44 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:44 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 218. Jul 19 14:01:44 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:44 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:44 chm-volumio go-librespot[7784]: Librespot-go daemon starting... Jul 19 14:01:44 chm-volumio go-librespot[7784]: time="2024-07-19T14:01:44+03:00" level=info msg="generated new device id: a0acf86c9274695b543dca1562519c247a9d47d2" Jul 19 14:01:44 chm-volumio go-librespot[7784]: time="2024-07-19T14:01:44+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:45 chm-volumio go-librespot[7784]: time="2024-07-19T14:01:45+03:00" level=debug msg="obtained new client token: AAAGxZUngElixSZF2sDkx/Bs8a+O85rRxZtPBCEtdwMtYgJrBaPmCO4G1Kaig+xAiTz7+fMWEPQwcUHLx2nekzyW+VtwJUD70Spxl9uLKPlPT6SYVM1T4jDIUXmo+Em/xT/xCubfPBhEqbpg5/8gGLBCY+9+WeQmo0/PBuITzRmFX6WP41AoSf3V1WseGiFvmx265oI3M/sxzCEp0kMGsDZY1rHSnOH2HNhogIZxNs7UKnU3Q5dLc8EJjJTL" Jul 19 14:01:45 chm-volumio go-librespot[7784]: time="2024-07-19T14:01:45+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:45 chm-volumio go-librespot[7784]: time="2024-07-19T14:01:45+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:45 chm-volumio go-librespot[7784]: time="2024-07-19T14:01:45+03:00" level=debug msg="completed challenge" Jul 19 14:01:46 chm-volumio go-librespot[7784]: time="2024-07-19T14:01:46+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:46 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:46 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:47 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:47 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:49 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:49 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 219. Jul 19 14:01:49 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:49 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:49 chm-volumio go-librespot[7793]: Librespot-go daemon starting... Jul 19 14:01:49 chm-volumio go-librespot[7793]: time="2024-07-19T14:01:49+03:00" level=info msg="generated new device id: 919a6c516fcfa8a981429f6b6d2f5146c75b0854" Jul 19 14:01:49 chm-volumio go-librespot[7793]: time="2024-07-19T14:01:49+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:49 chm-volumio go-librespot[7793]: time="2024-07-19T14:01:49+03:00" level=debug msg="obtained new client token: AAAIwQyT8IeowbVfDApjBhZJ/nCK8M5nQ5MM4v65/XiFNG7hYB0s9SxVk91quwfven2HFS+jl5Api1pxOK0O9r5drzYTgYhl9Lei38d1M48Xxjy0P+uIg3A/+4AmSXYVMoF2nJZOIYk/dub8qoUawtNxhy2+Ge0jjSDf54d4EZfhL1LwwinJN2YrUqerpn4Fn1cExxJyOBZ8cxhf9pMU7nC38KLciLpjXwtSEn23KsXbSUTRTdcpufRmlFMzZ9w=" Jul 19 14:01:49 chm-volumio go-librespot[7793]: time="2024-07-19T14:01:49+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:49 chm-volumio go-librespot[7793]: time="2024-07-19T14:01:49+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:49 chm-volumio volumio[930]: info: VolumeController::SetAlsaVolume69 Jul 19 14:01:49 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:49 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:49 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 19 14:01:49 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:49 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:49 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:49 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Jul 19 14:01:49 chm-volumio volumio[930]: SPOTIFY: SPOTIFY VOLUME 46 Jul 19 14:01:49 chm-volumio volumio[930]: SPOTIFY: VOLUMIO VOLUME 69 Jul 19 14:01:49 chm-volumio volumio[930]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 19 14:01:49 chm-volumio volumio[930]: info: Setting Spotify Volume from Volumio: 69 Jul 19 14:01:50 chm-volumio go-librespot[7793]: time="2024-07-19T14:01:50+03:00" level=debug msg="completed challenge" Jul 19 14:01:50 chm-volumio go-librespot[7793]: time="2024-07-19T14:01:50+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:50 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:50 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:50 chm-volumio volumio[930]: info: VolumeController::SetAlsaVolume100 Jul 19 14:01:50 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:50 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:50 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 19 14:01:50 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:50 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:50 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:50 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 19 14:01:50 chm-volumio volumio[930]: SPOTIFY: SPOTIFY VOLUME 69 Jul 19 14:01:50 chm-volumio volumio[930]: SPOTIFY: VOLUMIO VOLUME 100 Jul 19 14:01:50 chm-volumio volumio[930]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 19 14:01:50 chm-volumio volumio[930]: info: Setting Spotify Volume from Volumio: 100 Jul 19 14:01:50 chm-volumio volumiologrotate[589]: ls: cannot access '/var/log/samba/log.wb-CHM': No such file or directory Jul 19 14:01:50 chm-volumio volumiologrotate[589]: ls: cannot access 'VOLUMIO': No such file or directory Jul 19 14:01:50 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:50 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:51 chm-volumio volumio[930]: info: VolumeController::SetAlsaVolume80 Jul 19 14:01:51 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:51 chm-volumio volumio[930]: info: CoreStateMachine::pushState Jul 19 14:01:51 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 19 14:01:51 chm-volumio volumio[930]: info: CoreCommandRouter::volumioPushState Jul 19 14:01:51 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output update for this device Jul 19 14:01:51 chm-volumio volumio[930]: info: MRS: Pushing multiroomSync output Jul 19 14:01:51 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80 Jul 19 14:01:51 chm-volumio volumio[930]: SPOTIFY: SPOTIFY VOLUME 100 Jul 19 14:01:51 chm-volumio volumio[930]: SPOTIFY: VOLUMIO VOLUME 80 Jul 19 14:01:51 chm-volumio volumio[930]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 19 14:01:51 chm-volumio volumio[930]: info: Setting Spotify Volume from Volumio: 80 Jul 19 14:01:52 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: multiroom , disableAudioOutput Jul 19 14:01:52 chm-volumio volumio[930]: info: MRS: Setting this device as single Jul 19 14:01:52 chm-volumio volumio[930]: info: Jul 19 14:01:52 chm-volumio volumio[930]: [1721386912771] ---------------------------- Setting Multiroom Single Jul 19 14:01:52 chm-volumio volumio[930]: info: MRS: disable multiroom output Jul 19 14:01:52 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioDiscard Jul 19 14:01:52 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioDiscard Jul 19 14:01:53 chm-volumio volumio[930]: SPOTIFY: SETTING SPOTIFY VOLUME 80 Jul 19 14:01:53 chm-volumio volumio[930]: info: Sending Spotify command with payload to local API: /player/volume Jul 19 14:01:53 chm-volumio volumio[930]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:53 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:53 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 220. Jul 19 14:01:53 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:53 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:53 chm-volumio go-librespot[7846]: Librespot-go daemon starting... Jul 19 14:01:53 chm-volumio go-librespot[7846]: time="2024-07-19T14:01:53+03:00" level=info msg="generated new device id: 28cf8456af3cdcee209bef63eef558a283858c76" Jul 19 14:01:53 chm-volumio go-librespot[7846]: time="2024-07-19T14:01:53+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:53 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Jul 19 14:01:53 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioLocalPlayback Jul 19 14:01:53 chm-volumio go-librespot[7846]: time="2024-07-19T14:01:53+03:00" level=debug msg="obtained new client token: AACjo3KP0kAFDSaXDfU+OiVXeNCp8Svr0OOsvwfzhNjy9FZmhFISZfeGxjIW/JKFbCVrW4Hp0W9QAs1SN/LG9lkRCSJTodXY+DVuNkPMNPyko7PXvcVVkxAV0AG6ACDtzPS7nrFUx7kMCPIyTXF4vV1+uh6/qDvzNCl9WOThvOsghbtk9G0bkg6M+hDaNCDARBETb8AfPYBv8xBevm0m2R2XoqqCRgQkldEzD3pgplbh3x+j2ONZN3Jyql1H2LU=" Jul 19 14:01:53 chm-volumio go-librespot[7846]: time="2024-07-19T14:01:53+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:53 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:53 chm-volumio go-librespot[7846]: time="2024-07-19T14:01:53+03:00" level=debug msg="new websocket client" Jul 19 14:01:53 chm-volumio volumio[930]: info: Connection to go-librespot Websocket established Jul 19 14:01:53 chm-volumio go-librespot[7846]: time="2024-07-19T14:01:53+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:54 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: multiroom , enableAudioOutput Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: Starting cast device: DESKTOP-5FKU0RO Jul 19 14:01:54 chm-volumio volumio[930]: info: Enabled audio output: DESKTOP-5FKU0RO Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: Setting this device as Streaming Server Jul 19 14:01:54 chm-volumio volumio[930]: info: Jul 19 14:01:54 chm-volumio volumio[930]: [1721386914074] ---------------------------- MRS: Setting Streaming Server Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: enable multiroom server output Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioMultiRoom Jul 19 14:01:54 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioMultiRoom Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Jul 19 14:01:54 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioLocalPlayback Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: STARTING volumioStreaming Jul 19 14:01:54 chm-volumio sudo[7859]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/stream.m3u8 /tmp/hls/stream0.ts /tmp/hls/stream1.ts /tmp/hls/stream10.ts /tmp/hls/stream11.ts /tmp/hls/stream12.ts /tmp/hls/stream13.ts /tmp/hls/stream14.ts /tmp/hls/stream15.ts /tmp/hls/stream16.ts /tmp/hls/stream17.ts /tmp/hls/stream18.ts /tmp/hls/stream19.ts /tmp/hls/stream2.ts /tmp/hls/stream3.ts /tmp/hls/stream4.ts /tmp/hls/stream5.ts /tmp/hls/stream6.ts /tmp/hls/stream7.ts /tmp/hls/stream8.ts /tmp/hls/stream9.ts Jul 19 14:01:54 chm-volumio sudo[7859]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:54 chm-volumio sudo[7859]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:54 chm-volumio sudo[7862]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Jul 19 14:01:54 chm-volumio sudo[7862]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:54 chm-volumio systemd[1]: Stopping VolumioStreamingService... Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: Connected to cast device: DESKTOP-5FKU0RO Jul 19 14:01:54 chm-volumio systemd[1]: volumioStreaming.service: Main process exited, code=killed, status=15/TERM Jul 19 14:01:54 chm-volumio volumio[930]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: STOPPING volumioStreaming Jul 19 14:01:54 chm-volumio systemd[1]: volumioStreaming.service: Succeeded. Jul 19 14:01:54 chm-volumio systemd[1]: Stopped VolumioStreamingService. Jul 19 14:01:54 chm-volumio systemd[1]: Started VolumioStreamingService. Jul 19 14:01:54 chm-volumio sudo[7866]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Jul 19 14:01:54 chm-volumio sudo[7866]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:54 chm-volumio sudo[7862]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:54 chm-volumio sudo[7868]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:54 chm-volumio sudo[7868]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: Stopping cast device: DESKTOP-5FKU0RO Jul 19 14:01:54 chm-volumio systemd[1]: Stopping VolumioStreamingService... Jul 19 14:01:54 chm-volumio volumio[930]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jul 19 14:01:54 chm-volumio systemd[1]: volumioStreaming.service: Main process exited, code=killed, status=15/TERM Jul 19 14:01:54 chm-volumio sudo[7868]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:54 chm-volumio systemd[1]: volumioStreaming.service: Succeeded. Jul 19 14:01:54 chm-volumio sudo[7870]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:54 chm-volumio systemd[1]: Stopped VolumioStreamingService. Jul 19 14:01:54 chm-volumio sudo[7870]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: volumioStreaming STARTED Jul 19 14:01:54 chm-volumio sudo[7870]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:54 chm-volumio sudo[7866]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:54 chm-volumio volumio[930]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: volumioStreaming STOPPED Jul 19 14:01:54 chm-volumio volumio[930]: info: MRS: Removed streaming files Jul 19 14:01:54 chm-volumio go-librespot[7846]: time="2024-07-19T14:01:54+03:00" level=debug msg="completed challenge" Jul 19 14:01:54 chm-volumio go-librespot[7846]: time="2024-07-19T14:01:54+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:54 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:54 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:54 chm-volumio volumio[930]: info: Connection to go-librespot Websocket closed Jul 19 14:01:56 chm-volumio volumio[930]: info: Getting Spotify volume Jul 19 14:01:56 chm-volumio volumio[930]: (node:930) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:56 chm-volumio volumio[930]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 19 14:01:56 chm-volumio volumio[930]: (node:930) 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: 144) Jul 19 14:01:56 chm-volumio volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 19 14:01:56 chm-volumio volumio[930]: info: CoreCommandRouter::volumioGetState Jul 19 14:01:56 chm-volumio volumio[930]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80 Jul 19 14:01:57 chm-volumio volumio[930]: info: Initializing connection to go-librespot Websocket Jul 19 14:01:57 chm-volumio volumio[930]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 19 14:01:57 chm-volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 19 14:01:57 chm-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 221. Jul 19 14:01:57 chm-volumio systemd[1]: Stopped go-librespot Daemon. Jul 19 14:01:57 chm-volumio systemd[1]: Started go-librespot Daemon. Jul 19 14:01:57 chm-volumio go-librespot[7874]: Librespot-go daemon starting... Jul 19 14:01:57 chm-volumio go-librespot[7874]: time="2024-07-19T14:01:57+03:00" level=info msg="generated new device id: 356f75ef7796b69d1456f89d7563ff76adbc4ce9" Jul 19 14:01:57 chm-volumio go-librespot[7874]: time="2024-07-19T14:01:57+03:00" level=debug msg="stored credentials found for sofosmavros" Jul 19 14:01:57 chm-volumio go-librespot[7874]: time="2024-07-19T14:01:57+03:00" level=debug msg="obtained new client token: AAA2t5yhY2412CVHszw+UPafUtbnBdNUbbj56L88+zxUKTRgplHyvYsgkvzBfticMtf/sl/ulyEeSYSuvLmmzPBuDnnSks0Agg0QrFZLL5IKydWDnr8WVdtmnGIVjdD9S1yjYMjFpi0LpmOOGfku0MQ7TGwpdvP1+3Zj8QvEetGn7E0d1UMesbbQ+olHltsjM5Fa81FNm6E3WyV/RxHdGr9hCXBL5vZHv2PpwX5/FbW21SWDi0kKdT7Kc4AnPic=" Jul 19 14:01:58 chm-volumio go-librespot[7874]: time="2024-07-19T14:01:58+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jul 19 14:01:58 chm-volumio go-librespot[7874]: time="2024-07-19T14:01:58+03:00" level=debug msg="completed keyexchange" Jul 19 14:01:58 chm-volumio go-librespot[7874]: time="2024-07-19T14:01:58+03:00" level=debug msg="completed challenge" Jul 19 14:01:58 chm-volumio go-librespot[7874]: time="2024-07-19T14:01:58+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 19 14:01:58 chm-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 19 14:01:58 chm-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 19 14:01:59 chm-volumio volumio[930]: info: CoreCommandRouter::executeOnPlugin: multiroom , enableAudioOutput Jul 19 14:01:59 chm-volumio volumio[930]: info: MRS: Starting cast device: DESKTOP-5FKU0RO Jul 19 14:01:59 chm-volumio volumio[930]: info: Enabled audio output: DESKTOP-5FKU0RO Jul 19 14:01:59 chm-volumio volumio[930]: info: MRS: Setting this device as Streaming Server Jul 19 14:01:59 chm-volumio volumio[930]: info: Jul 19 14:01:59 chm-volumio volumio[930]: [1721386919012] ---------------------------- MRS: Setting Streaming Server Jul 19 14:01:59 chm-volumio volumio[930]: info: MRS: enable multiroom server output Jul 19 14:01:59 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioMultiRoom Jul 19 14:01:59 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioMultiRoom Jul 19 14:01:59 chm-volumio volumio[930]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Jul 19 14:01:59 chm-volumio volumio[930]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioLocalPlayback Jul 19 14:01:59 chm-volumio volumio[930]: info: MRS: STARTING volumioStreaming Jul 19 14:01:59 chm-volumio sudo[7885]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:59 chm-volumio sudo[7885]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:59 chm-volumio sudo[7885]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:59 chm-volumio volumio[930]: info: MRS: Connected to cast device: DESKTOP-5FKU0RO Jul 19 14:01:59 chm-volumio sudo[7888]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Jul 19 14:01:59 chm-volumio sudo[7888]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:59 chm-volumio volumio[930]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 19 14:01:59 chm-volumio volumio[930]: TypeError: Cannot read property 'on' of undefined Jul 19 14:01:59 chm-volumio volumio[930]: at /myvolumio/plugins/audio_interface/multiroom/multiroom_real:1:29162 Jul 19 14:01:59 chm-volumio volumio[930]: at /myvolumio/plugins/audio_interface/multiroom/node_modules/castv2-client/lib/senders/platform.js:95:20 Jul 19 14:01:59 chm-volumio volumio[930]: at /myvolumio/plugins/audio_interface/multiroom/node_modules/castv2-client/lib/controllers/receiver.js:51:14 Jul 19 14:01:59 chm-volumio volumio[930]: at fn.onmessage (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2-client/lib/controllers/request-response.js:27:7) Jul 19 14:01:59 chm-volumio volumio[930]: at fn.emit (events.js:327:22) Jul 19 14:01:59 chm-volumio volumio[930]: at Channel.onmessage (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2-client/lib/controllers/controller.js:16:10) Jul 19 14:01:59 chm-volumio volumio[930]: at Channel.emit (events.js:315:20) Jul 19 14:01:59 chm-volumio volumio[930]: at Client.onmessage (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2/lib/channel.js:23:10) Jul 19 14:01:59 chm-volumio volumio[930]: at Client.emit (events.js:327:22) Jul 19 14:01:59 chm-volumio volumio[930]: at PacketStreamWrapper.onpacket (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2/lib/client.js:81:10) Jul 19 14:01:59 chm-volumio volumio[930]: at PacketStreamWrapper.emit (events.js:315:20) Jul 19 14:01:59 chm-volumio volumio[930]: at TLSSocket. (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2/lib/packet-stream-wrapper.js:28:16) Jul 19 14:01:59 chm-volumio volumio[930]: at TLSSocket.emit (events.js:315:20) Jul 19 14:01:59 chm-volumio volumio[930]: at emitReadable_ (internal/streams/readable.js:569:12) Jul 19 14:01:59 chm-volumio volumio[930]: at processTicksAndRejections (internal/process/task_queues.js:79:21) Jul 19 14:01:59 chm-volumio volumio[930]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 19 14:01:59 chm-volumio systemd[1]: Started VolumioStreamingService. Jul 19 14:01:59 chm-volumio sudo[7888]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:59 chm-volumio sudo[7892]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jul 19 14:01:59 chm-volumio sudo[7892]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 19 14:01:59 chm-volumio sudo[7892]: pam_unix(sudo:session): session closed for user root Jul 19 14:01:59 chm-volumio sudo[7903]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-19 14:00 Jul 19 14:01:59 chm-volumio sudo[7903]: 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="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 08:41:12 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="8e78a6e3f56f1bcbbd1760812129a8e9"