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