-- Logs begin at Tue 2024-10-08 21:51:55 CST, end at Tue 2024-10-08 23:41:56 CST. -- Oct 08 23:40:00 my-player go-librespot[22247]: time="2024-10-08T23:40:00+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:40:00 my-player go-librespot[22247]: time="2024-10-08T23:40:00+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:40:00 my-player go-librespot[22247]: time="2024-10-08T23:40:00+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:40:00 my-player go-librespot[22247]: time="2024-10-08T23:40:00+08:00" level=debug msg="zeroconf server listening on port 41193" Oct 08 23:40:01 my-player go-librespot[22247]: time="2024-10-08T23:40:01+08:00" level=debug msg="obtained new client token: AABdl8GJ/bzRBl+LCi7gls3qLxsMNRHh3T7SUU+gMs9Xke5C/YZNDZRMqgVI8PHLHb2z8pZTlcWewAmHGhcccEdfnc9vRaBt36jKTNXxkIQUE+K/4i1mFTsQOvkiEQIRp5XXfQ8g3QwBnAeE9nRN3bJOZv5OOstB/mx3KihrM/zZma+K1QcLEpGMrdmqytxEMWMS7ZiTVsfDvB1QNkHjRuFDtS/CI56xR+YmpDf3Dl5Pkb08ot5LKcclJVFRt9Zm" Oct 08 23:40:01 my-player go-librespot[22247]: time="2024-10-08T23:40:01+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:40:01 my-player go-librespot[22247]: time="2024-10-08T23:40:01+08:00" level=debug msg="completed keyexchange" Oct 08 23:40:02 my-player go-librespot[22247]: time="2024-10-08T23:40:02+08:00" level=debug msg="completed challenge" Oct 08 23:40:02 my-player go-librespot[22247]: time="2024-10-08T23:40:02+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:40:02 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:40:02 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:40:02 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:02 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:05 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:40:05 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 852. Oct 08 23:40:05 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:40:05 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:40:05 my-player go-librespot[22256]: Librespot-go daemon starting... Oct 08 23:40:05 my-player go-librespot[22256]: time="2024-10-08T23:40:05+08:00" level=info msg="generated new device id: 3761770c8dce874b6fffed2737e94b2b33958974" Oct 08 23:40:05 my-player go-librespot[22256]: time="2024-10-08T23:40:05+08:00" level=debug msg="stored credentials not found" Oct 08 23:40:05 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:05 my-player go-librespot[22256]: time="2024-10-08T23:40:05+08:00" level=debug msg="new websocket client" Oct 08 23:40:05 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:40:06 my-player go-librespot[22256]: time="2024-10-08T23:40:06+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 08 23:40:06 my-player go-librespot[22256]: time="2024-10-08T23:40:06+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 08 23:40:06 my-player go-librespot[22256]: time="2024-10-08T23:40:06+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 08 23:40:06 my-player go-librespot[22256]: time="2024-10-08T23:40:06+08:00" level=debug msg="zeroconf server listening on port 32799" Oct 08 23:40:07 my-player go-librespot[22256]: time="2024-10-08T23:40:07+08:00" level=debug msg="obtained new client token: AAAmsTRTNVadhfXQt+IK8d6b6bkNqHyPjlE3M6DftSc4cRPASEHGd3S659KagpWUIWUaJ+WS6HEitxCcdjiKUDNAN5Bpvop0ZTB6kvOREO3FlE6G9sMW1h0v4+U8W05V738/onz1Rt/33AfYge2jsCsiZtKe7il36mrDwiU5Oo1LeqjF9W4J/d2g9VITGI2JTYBzf8MZjxfq6s6I12mQX/cWcjGKlFDtqypHSj3f5fo59ig4yf58MJJk40tWy9cQ" Oct 08 23:40:07 my-player go-librespot[22256]: time="2024-10-08T23:40:07+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:40:07 my-player go-librespot[22256]: time="2024-10-08T23:40:07+08:00" level=debug msg="completed keyexchange" Oct 08 23:40:07 my-player go-librespot[22256]: time="2024-10-08T23:40:07+08:00" level=debug msg="completed challenge" Oct 08 23:40:07 my-player go-librespot[22256]: time="2024-10-08T23:40:07+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:40:07 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:40:07 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:40:07 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:40:08 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:40:08 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:08 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:40:08 my-player volumio[6703]: (node:6703) 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: 504) Oct 08 23:40:08 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 08 23:40:08 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:40:08 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:40:08 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:40:10 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:10 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:11 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:40:11 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 853. Oct 08 23:40:11 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:40:11 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:40:11 my-player go-librespot[22264]: Librespot-go daemon starting... Oct 08 23:40:11 my-player go-librespot[22264]: time="2024-10-08T23:40:11+08:00" level=info msg="generated new device id: 31157b7ade5d18e9677d561c6b208517c7bc72bd" Oct 08 23:40:11 my-player go-librespot[22264]: time="2024-10-08T23:40:11+08:00" level=debug msg="stored credentials not found" Oct 08 23:40:11 my-player go-librespot[22264]: time="2024-10-08T23:40:11+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:40:11 my-player go-librespot[22264]: time="2024-10-08T23:40:11+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:40:11 my-player go-librespot[22264]: time="2024-10-08T23:40:11+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:40:11 my-player go-librespot[22264]: time="2024-10-08T23:40:11+08:00" level=debug msg="zeroconf server listening on port 40313" Oct 08 23:40:12 my-player go-librespot[22264]: time="2024-10-08T23:40:12+08:00" level=debug msg="obtained new client token: AABaLQTe4zIk/gVHwsctxRAK4mFlvDAZpHR4RSPj5/Qp+csoHMgLwMayNJuv3PP+V0Xbtxi8DJVOfmiMxX8s1+FvXBlmiWjStWx+xvAxGaQE8TrDS72+1NF9xtnKJOTh/zsBwV/gQznY+ydrRZYcUFFprniOTCAqm2j5HuCWP6pJ9AMMTWgQJfpqrpxEFaDPOBazUNDhJJnMEH7Doz4xBIp2F5lgdWfgAdm1qZIz2I0KpA4LYhINLzazujT8X+vF" Oct 08 23:40:12 my-player go-librespot[22264]: time="2024-10-08T23:40:12+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:40:12 my-player go-librespot[22264]: time="2024-10-08T23:40:12+08:00" level=debug msg="completed keyexchange" Oct 08 23:40:13 my-player go-librespot[22264]: time="2024-10-08T23:40:13+08:00" level=debug msg="completed challenge" Oct 08 23:40:13 my-player go-librespot[22264]: time="2024-10-08T23:40:13+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:40:13 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:40:13 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:40:13 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:13 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:16 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:40:16 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 854. Oct 08 23:40:16 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:40:16 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:40:16 my-player go-librespot[22272]: Librespot-go daemon starting... Oct 08 23:40:16 my-player go-librespot[22272]: time="2024-10-08T23:40:16+08:00" level=info msg="generated new device id: 45d8ad1e8403c30fd882a62ea98e05eab9e1752a" Oct 08 23:40:16 my-player go-librespot[22272]: time="2024-10-08T23:40:16+08:00" level=debug msg="stored credentials not found" Oct 08 23:40:16 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:16 my-player go-librespot[22272]: time="2024-10-08T23:40:16+08:00" level=debug msg="new websocket client" Oct 08 23:40:16 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:40:17 my-player go-librespot[22272]: time="2024-10-08T23:40:17+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 08 23:40:17 my-player go-librespot[22272]: time="2024-10-08T23:40:17+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 08 23:40:17 my-player go-librespot[22272]: time="2024-10-08T23:40:17+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 08 23:40:17 my-player go-librespot[22272]: time="2024-10-08T23:40:17+08:00" level=debug msg="zeroconf server listening on port 43787" Oct 08 23:40:18 my-player go-librespot[22272]: time="2024-10-08T23:40:18+08:00" level=debug msg="obtained new client token: AAADG5JKiFM55bgnA/Kdj3vtPhe/k9p9SmWdpeDgWPg29yM+qH3bzGMstjl2+ZnCqu+wijjUx3rrgK7jis41bYWoWU7qlMgkHbk1R/DfZWCB1s7uELr2jgrFHotm1eMdZ2ibt0dSv+zi5ltVK9PT6tqZkYVT0Ozcv/oFpZuD6mxvPj5dUv5V+kbroAkbL3npUpoY5kv0dfnk1jZCqFnRzrA6EF9jc01m9F5Q2kdFc7LQ2pePrMPSJXm4+s02KA==" Oct 08 23:40:18 my-player go-librespot[22272]: time="2024-10-08T23:40:18+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:40:18 my-player go-librespot[22272]: time="2024-10-08T23:40:18+08:00" level=debug msg="completed keyexchange" Oct 08 23:40:18 my-player go-librespot[22272]: time="2024-10-08T23:40:18+08:00" level=debug msg="completed challenge" Oct 08 23:40:18 my-player go-librespot[22272]: time="2024-10-08T23:40:18+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:40:18 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:40:18 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:40:18 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:40:19 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:40:19 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:19 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:40:19 my-player volumio[6703]: (node:6703) 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: 505) Oct 08 23:40:19 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 08 23:40:19 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:40:19 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:40:19 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:40:21 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:21 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:22 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:40:22 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 855. Oct 08 23:40:22 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:40:22 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:40:22 my-player go-librespot[22282]: Librespot-go daemon starting... Oct 08 23:40:22 my-player go-librespot[22282]: time="2024-10-08T23:40:22+08:00" level=info msg="generated new device id: 91c213d0eb05ec8744b4a90fbdc46512ade2b75c" Oct 08 23:40:22 my-player go-librespot[22282]: time="2024-10-08T23:40:22+08:00" level=debug msg="stored credentials not found" Oct 08 23:40:22 my-player go-librespot[22282]: time="2024-10-08T23:40:22+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:40:22 my-player go-librespot[22282]: time="2024-10-08T23:40:22+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:40:22 my-player go-librespot[22282]: time="2024-10-08T23:40:22+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:40:22 my-player go-librespot[22282]: time="2024-10-08T23:40:22+08:00" level=debug msg="zeroconf server listening on port 45193" Oct 08 23:40:23 my-player go-librespot[22282]: time="2024-10-08T23:40:23+08:00" level=debug msg="obtained new client token: AACidRNREfHQayaUtdOkKR/j82bNXxpBJTZKCVTaYQ1i99gc7r2zlIQM8MUXqKAFlojWf0ZhT8nLbrXG14ADtdaCUeNUwxxiYwpToTz5bZwqU3Pjx+IqML0apZ4k48OCmSpn5Q5E9BRE0zSncah7U9hR5Hx9hYtjNE9uw6lvRsK6l8Blwyj08iP0erMoTnTHENU7wyfeW/JJIqa6qwLcIHCAF3jzPzan9R0mZmDoYJslkfltc1t+t3qfqc589mdB" Oct 08 23:40:23 my-player go-librespot[22282]: time="2024-10-08T23:40:23+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:40:23 my-player go-librespot[22282]: time="2024-10-08T23:40:23+08:00" level=debug msg="completed keyexchange" Oct 08 23:40:24 my-player go-librespot[22282]: time="2024-10-08T23:40:24+08:00" level=debug msg="completed challenge" Oct 08 23:40:24 my-player go-librespot[22282]: time="2024-10-08T23:40:24+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:40:24 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:40:24 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:40:24 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:24 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:27 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:40:27 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 856. Oct 08 23:40:27 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:40:27 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:40:27 my-player go-librespot[22290]: Librespot-go daemon starting... Oct 08 23:40:27 my-player go-librespot[22290]: time="2024-10-08T23:40:27+08:00" level=info msg="generated new device id: 87e649ccafc101c1510d7b9bc49b95683f0f4cf1" Oct 08 23:40:27 my-player go-librespot[22290]: time="2024-10-08T23:40:27+08:00" level=debug msg="stored credentials not found" Oct 08 23:40:27 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:27 my-player go-librespot[22290]: time="2024-10-08T23:40:27+08:00" level=debug msg="new websocket client" Oct 08 23:40:28 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:40:28 my-player go-librespot[22290]: time="2024-10-08T23:40:28+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 08 23:40:28 my-player go-librespot[22290]: time="2024-10-08T23:40:28+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 08 23:40:28 my-player go-librespot[22290]: time="2024-10-08T23:40:28+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 08 23:40:28 my-player go-librespot[22290]: time="2024-10-08T23:40:28+08:00" level=debug msg="zeroconf server listening on port 34769" Oct 08 23:40:29 my-player go-librespot[22290]: time="2024-10-08T23:40:29+08:00" level=debug msg="obtained new client token: AAATAmLPALGioBk93xPJK42jpaaVbRmg1dPC8MnSzwgwkrrjHSU0hHC/1aLckchFB7KL5CZpSZhrBXQf0bR8a5LyxzGKnp95trlKmzuNcS906edSLBruKkcOGuK4Z6LJECiITTGKYR1rkP3kP6WryV4QLebB0Uo66TBTYhdUknGcAITu9eRa8WHcWQzv5GUNqumYV67usOxPQIr4P3Ep8JVB/jufM38gvS1Oo6dzSQMoD/dFLLIegYmMsT36sg==" Oct 08 23:40:29 my-player go-librespot[22290]: time="2024-10-08T23:40:29+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:40:29 my-player go-librespot[22290]: time="2024-10-08T23:40:29+08:00" level=debug msg="completed keyexchange" Oct 08 23:40:30 my-player go-librespot[22290]: time="2024-10-08T23:40:30+08:00" level=debug msg="completed challenge" Oct 08 23:40:30 my-player go-librespot[22290]: time="2024-10-08T23:40:30+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:40:30 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:40:30 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:40:30 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:40:31 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:40:31 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:31 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:40:31 my-player volumio[6703]: (node:6703) 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: 507) Oct 08 23:40:31 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 08 23:40:31 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:40:31 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:40:31 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:40:33 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:33 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:33 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:40:33 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 857. Oct 08 23:40:33 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:40:33 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:40:33 my-player go-librespot[22298]: Librespot-go daemon starting... Oct 08 23:40:33 my-player go-librespot[22298]: time="2024-10-08T23:40:33+08:00" level=info msg="generated new device id: 42026e99446221c29e1e4e6bcc6295e8ea9ffe94" Oct 08 23:40:33 my-player go-librespot[22298]: time="2024-10-08T23:40:33+08:00" level=debug msg="stored credentials not found" Oct 08 23:40:34 my-player go-librespot[22298]: time="2024-10-08T23:40:34+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:40:34 my-player go-librespot[22298]: time="2024-10-08T23:40:34+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:40:34 my-player go-librespot[22298]: time="2024-10-08T23:40:34+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:40:34 my-player go-librespot[22298]: time="2024-10-08T23:40:34+08:00" level=debug msg="zeroconf server listening on port 45907" Oct 08 23:40:36 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:36 my-player go-librespot[22298]: time="2024-10-08T23:40:36+08:00" level=debug msg="new websocket client" Oct 08 23:40:36 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:40:36 my-player volumiologrotate[794]: ls: cannot access '/var/log/samba/log.wb-MY': No such file or directory Oct 08 23:40:36 my-player volumiologrotate[794]: ls: cannot access 'PLAYER': No such file or directory Oct 08 23:40:37 my-player go-librespot[22298]: time="2024-10-08T23:40:37+08:00" level=debug msg="obtained new client token: AADJQHC4gRe1GMXn/h7JrpAV2OAx/tw3q9k797nNwcX7lW/UJxaXc2PEwZajAZ64+aRNvgZfdtjZmpkaw3+iTu2nxm/FBBhzRDQTAq5cAwiLM+aLIkSHKKOJB+NOziH/SVPgpZCbAwaKMctE0LHjl+YlqefFH8RZlWDbY9E/j4dnRWrnQHygsV8NsdaHwmD8frojc/c2vKHsw4MLZhMR+AX1Koc9wnQt/eM2TqEqGH8ZuIu54SxEGfbi4SVjKVnv" Oct 08 23:40:37 my-player go-librespot[22298]: time="2024-10-08T23:40:37+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:40:37 my-player go-librespot[22298]: time="2024-10-08T23:40:37+08:00" level=debug msg="completed keyexchange" Oct 08 23:40:37 my-player go-librespot[22298]: time="2024-10-08T23:40:37+08:00" level=debug msg="completed challenge" Oct 08 23:40:37 my-player go-librespot[22298]: time="2024-10-08T23:40:37+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:40:37 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:40:37 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:40:37 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:40:39 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:40:39 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:39 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:40:39 my-player volumio[6703]: (node:6703) 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: 508) Oct 08 23:40:39 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 08 23:40:39 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:40:39 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:40:39 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:40:40 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:40 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:40 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:40:40 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 858. Oct 08 23:40:40 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:40:40 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:40:40 my-player go-librespot[22353]: Librespot-go daemon starting... Oct 08 23:40:40 my-player go-librespot[22353]: time="2024-10-08T23:40:40+08:00" level=info msg="generated new device id: a587edc941b0030f16f3d239b89a78a21a4196bb" Oct 08 23:40:40 my-player go-librespot[22353]: time="2024-10-08T23:40:40+08:00" level=debug msg="stored credentials not found" Oct 08 23:40:41 my-player go-librespot[22353]: time="2024-10-08T23:40:41+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:40:41 my-player go-librespot[22353]: time="2024-10-08T23:40:41+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:40:41 my-player go-librespot[22353]: time="2024-10-08T23:40:41+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:40:41 my-player go-librespot[22353]: time="2024-10-08T23:40:41+08:00" level=debug msg="zeroconf server listening on port 36583" Oct 08 23:40:42 my-player go-librespot[22353]: time="2024-10-08T23:40:42+08:00" level=debug msg="obtained new client token: AAAH7HEyEUIE8PJ7AOI39D3JVxVWoHVKvmMzAsrwIDmEOT+UTpHyKgyK9q08RDmkDNsMVenFkHnBIVhhdjPYId4lBlaFezkapbZ9crveY8bZAwNoB+F9JuhpvKGMrX0EaaXxW0U2QvVQ6/FqkJKGOOZGXuT5Z6ONeO+RfLe3MkXfajJrFFZ1gcyb0OphIx3eV3ci3zledS+W4tFy0ixzlrfyHIr9xc3QDgRRJkP+WoF/O/WnT5HXVEXfAfSE84ND" Oct 08 23:40:42 my-player go-librespot[22353]: time="2024-10-08T23:40:42+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:40:42 my-player go-librespot[22353]: time="2024-10-08T23:40:42+08:00" level=debug msg="completed keyexchange" Oct 08 23:40:43 my-player go-librespot[22353]: time="2024-10-08T23:40:43+08:00" level=debug msg="completed challenge" Oct 08 23:40:43 my-player go-librespot[22353]: time="2024-10-08T23:40:43+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:40:43 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:40:43 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:40:43 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:43 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:46 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:40:46 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 859. Oct 08 23:40:46 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:40:46 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:40:46 my-player go-librespot[22362]: Librespot-go daemon starting... Oct 08 23:40:46 my-player go-librespot[22362]: time="2024-10-08T23:40:46+08:00" level=info msg="generated new device id: 76d9aef93faab19e61f5376917bb7a97e53cea58" Oct 08 23:40:46 my-player go-librespot[22362]: time="2024-10-08T23:40:46+08:00" level=debug msg="stored credentials not found" Oct 08 23:40:46 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:46 my-player go-librespot[22362]: time="2024-10-08T23:40:46+08:00" level=debug msg="new websocket client" Oct 08 23:40:46 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:40:47 my-player go-librespot[22362]: time="2024-10-08T23:40:47+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 08 23:40:47 my-player go-librespot[22362]: time="2024-10-08T23:40:47+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 08 23:40:47 my-player go-librespot[22362]: time="2024-10-08T23:40:47+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 08 23:40:47 my-player go-librespot[22362]: time="2024-10-08T23:40:47+08:00" level=debug msg="zeroconf server listening on port 38087" Oct 08 23:40:47 my-player go-librespot[22362]: time="2024-10-08T23:40:47+08:00" level=debug msg="obtained new client token: AAACbuAT4ECNscVA/wD0REu2g5IMTxVdnvzogeK/UGYlR9hmYXbNyPr0XiNa3hzLGErFdwBX4dc8kwml6VyYdtdtSdoYVbvCm/8AcDwMJnLj7vSlhQgtzy/mAdOcbAqV5D4bZArRfPx3k5suIHIHNsP12XEkyzNVpIzJ2Yxkw7Ca36uVisPxE8YoRhp0tpK61v7pMWZHZybYh8vAXzasKMumJy/1sMvLw1og4p0GdIu6mN2ouis1BoXCaUywEMsQ" Oct 08 23:40:47 my-player go-librespot[22362]: time="2024-10-08T23:40:47+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:40:48 my-player go-librespot[22362]: time="2024-10-08T23:40:48+08:00" level=debug msg="completed keyexchange" Oct 08 23:40:48 my-player go-librespot[22362]: time="2024-10-08T23:40:48+08:00" level=debug msg="completed challenge" Oct 08 23:40:48 my-player go-librespot[22362]: time="2024-10-08T23:40:48+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:40:48 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:40:48 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:40:48 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:40:49 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:40:49 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:49 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:40:49 my-player volumio[6703]: (node:6703) 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: 509) Oct 08 23:40:49 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 08 23:40:49 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:40:49 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:40:49 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:40:51 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:51 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:51 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:40:51 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 860. Oct 08 23:40:51 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:40:51 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:40:51 my-player go-librespot[22370]: Librespot-go daemon starting... Oct 08 23:40:51 my-player go-librespot[22370]: time="2024-10-08T23:40:51+08:00" level=info msg="generated new device id: 98a19886e9c5236f3656166bf016955a5e848b36" Oct 08 23:40:51 my-player go-librespot[22370]: time="2024-10-08T23:40:51+08:00" level=debug msg="stored credentials not found" Oct 08 23:40:54 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:54 my-player go-librespot[22370]: time="2024-10-08T23:40:54+08:00" level=debug msg="new websocket client" Oct 08 23:40:54 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:40:55 my-player go-librespot[22370]: time="2024-10-08T23:40:55+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:40:55 my-player go-librespot[22370]: time="2024-10-08T23:40:55+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:40:55 my-player go-librespot[22370]: time="2024-10-08T23:40:55+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:40:55 my-player go-librespot[22370]: time="2024-10-08T23:40:55+08:00" level=debug msg="zeroconf server listening on port 33077" Oct 08 23:40:56 my-player go-librespot[22370]: time="2024-10-08T23:40:56+08:00" level=debug msg="obtained new client token: AACdux27sXO6CsiZCOKoJ44f9hxVizyIOaUSDvMUk+bvRR02sqVbBzUrNeA5RaZJDeXo7vcy+C1apTX/TEcNTpqrZcR8w15vHlPO8rmvH0yrsp+MHKPD2060zSgargsUPDLrtQZK88MdWm9owgxySbUh1KevKkPcXpuWLo+fjzHq3SwpVk6brKy92Z2Vn/zerESbwC7LSsCamNYTcVvrvGbtJAhUgMopvDLbaJLTdQyq7tHANh5RuE56E/juuUaq" Oct 08 23:40:56 my-player go-librespot[22370]: time="2024-10-08T23:40:56+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:40:56 my-player go-librespot[22370]: time="2024-10-08T23:40:56+08:00" level=debug msg="completed keyexchange" Oct 08 23:40:56 my-player go-librespot[22370]: time="2024-10-08T23:40:56+08:00" level=debug msg="completed challenge" Oct 08 23:40:56 my-player go-librespot[22370]: time="2024-10-08T23:40:56+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:40:56 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:40:56 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:40:56 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:40:57 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:40:57 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:57 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:40:57 my-player volumio[6703]: (node:6703) 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: 510) Oct 08 23:40:57 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 08 23:40:57 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:40:57 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:40:57 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:40:59 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:40:59 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:40:59 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:40:59 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 861. Oct 08 23:40:59 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:40:59 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:40:59 my-player go-librespot[22380]: Librespot-go daemon starting... Oct 08 23:40:59 my-player go-librespot[22380]: time="2024-10-08T23:40:59+08:00" level=info msg="generated new device id: ce4c2d2544f094e8dfaa9e33fdaaff5763569909" Oct 08 23:40:59 my-player go-librespot[22380]: time="2024-10-08T23:40:59+08:00" level=debug msg="stored credentials not found" Oct 08 23:41:00 my-player go-librespot[22380]: time="2024-10-08T23:41:00+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:41:00 my-player go-librespot[22380]: time="2024-10-08T23:41:00+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:41:00 my-player go-librespot[22380]: time="2024-10-08T23:41:00+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:41:00 my-player go-librespot[22380]: time="2024-10-08T23:41:00+08:00" level=debug msg="zeroconf server listening on port 36769" Oct 08 23:41:01 my-player go-librespot[22380]: time="2024-10-08T23:41:01+08:00" level=debug msg="obtained new client token: AADjSesT/bi6JBJObn5P1VwjliXVnCyJDa98hD0sGyvSdSjo3z1zS2+vWEyRVL4/Jnn04eRcEIXT9U7jEyA8VQTaPWA/sytfKN+my7lxLc86/Owy56oPyY/Er7n7uowdb6jjs4NHJuAjZpqLP47WU3+FN/ownSYAictMUSUqWeESm4Wm7uLGYp2xcdkPUVTqlby2JmN7G20VsGNIZl5F7FXorsD1WTbkkoil8V+z4GXEiblLYyK95WAJUAnwex0s" Oct 08 23:41:01 my-player go-librespot[22380]: time="2024-10-08T23:41:01+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:41:01 my-player go-librespot[22380]: time="2024-10-08T23:41:01+08:00" level=debug msg="completed keyexchange" Oct 08 23:41:02 my-player go-librespot[22380]: time="2024-10-08T23:41:02+08:00" level=debug msg="completed challenge" Oct 08 23:41:02 my-player go-librespot[22380]: time="2024-10-08T23:41:02+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:41:02 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:41:02 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:41:02 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:02 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:05 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:41:05 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 862. Oct 08 23:41:05 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:41:05 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:41:05 my-player go-librespot[22389]: Librespot-go daemon starting... Oct 08 23:41:05 my-player go-librespot[22389]: time="2024-10-08T23:41:05+08:00" level=info msg="generated new device id: b3e197a8aba4ac57017e694250944ec49870cf4e" Oct 08 23:41:05 my-player go-librespot[22389]: time="2024-10-08T23:41:05+08:00" level=debug msg="stored credentials not found" Oct 08 23:41:05 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:05 my-player go-librespot[22389]: time="2024-10-08T23:41:05+08:00" level=debug msg="new websocket client" Oct 08 23:41:05 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:41:06 my-player go-librespot[22389]: time="2024-10-08T23:41:06+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:41:06 my-player go-librespot[22389]: time="2024-10-08T23:41:06+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:41:06 my-player go-librespot[22389]: time="2024-10-08T23:41:06+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:41:06 my-player go-librespot[22389]: time="2024-10-08T23:41:06+08:00" level=debug msg="zeroconf server listening on port 38971" Oct 08 23:41:07 my-player go-librespot[22389]: time="2024-10-08T23:41:07+08:00" level=debug msg="obtained new client token: AABcu6eUs4mPbYXKyMT8arwKlC+aGhhevPJ960AVQyuv1SyDHeIMLeODpgU62tN8TwNw+OXWHJWsE8lSg6G9XW6iw4wzcnrg9VZJKW716wO+f8Fr+d7F1mRDVHkZK97b3U5TMUXNKFoXpi6R/gJuDEULNXH3W9/cIaJ6AuhrYa13fdH3STkbvYKlFx33mIAFUrylgBz24ji5VOcgoROOaPm4VKzJWcsA7eXEjAsmcg4JQv6ky4Cwz+80CYWLXw==" Oct 08 23:41:07 my-player go-librespot[22389]: time="2024-10-08T23:41:07+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070 (error: dial tcp 104.199.241.202:4070: connect: connection refused), retrying with a different AP" Oct 08 23:41:07 my-player go-librespot[22389]: time="2024-10-08T23:41:07+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:443 (error: dial tcp 104.199.241.202:443: connect: connection refused), retrying with a different AP" Oct 08 23:41:07 my-player go-librespot[22389]: time="2024-10-08T23:41:07+08:00" level=info msg="connected to ap-gae2.spotify.com:80" Oct 08 23:41:07 my-player go-librespot[22389]: time="2024-10-08T23:41:07+08:00" level=debug msg="completed keyexchange" Oct 08 23:41:08 my-player go-librespot[22389]: time="2024-10-08T23:41:08+08:00" level=debug msg="completed challenge" Oct 08 23:41:08 my-player go-librespot[22389]: time="2024-10-08T23:41:08+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:41:08 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:41:08 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:41:08 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:41:08 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:41:08 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:08 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:41:08 my-player volumio[6703]: (node:6703) 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: 511) Oct 08 23:41:08 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 08 23:41:08 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:08 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:08 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:11 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:11 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:11 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:41:11 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 863. Oct 08 23:41:11 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:41:11 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:41:11 my-player go-librespot[22397]: Librespot-go daemon starting... Oct 08 23:41:11 my-player go-librespot[22397]: time="2024-10-08T23:41:11+08:00" level=info msg="generated new device id: 8d3e3da2f08ae5a347296c8af2d466c5d18ad125" Oct 08 23:41:11 my-player go-librespot[22397]: time="2024-10-08T23:41:11+08:00" level=debug msg="stored credentials not found" Oct 08 23:41:12 my-player go-librespot[22397]: time="2024-10-08T23:41:12+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 08 23:41:12 my-player go-librespot[22397]: time="2024-10-08T23:41:12+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 08 23:41:12 my-player go-librespot[22397]: time="2024-10-08T23:41:12+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 08 23:41:12 my-player go-librespot[22397]: time="2024-10-08T23:41:12+08:00" level=debug msg="zeroconf server listening on port 43021" Oct 08 23:41:12 my-player go-librespot[22397]: time="2024-10-08T23:41:12+08:00" level=debug msg="obtained new client token: AAAr6YxjkE0oHt8S9yG643lm49r3oqWO73Qe6j1Cug+l50TtL4ortGYJ+0o+PUPicgQAOgrYPoC73KO3onklwmu3ZyPa0KU1sb8Mqh2Rf1UsrhEKkVaOZbBo6q0gK1Y6Ggo0g+0srZBSug/ytu282bfHUrbra90DAXJdV0AgJyqmV5uMNelXr+93o3mcNLIdOVnvZaRb7CwFTcOnF7ZsbJfh5tn+Xoqb2dmU/giqdUfAzAM3U9+cvoX3+u3apm8d" Oct 08 23:41:13 my-player go-librespot[22397]: time="2024-10-08T23:41:13+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:41:13 my-player go-librespot[22397]: time="2024-10-08T23:41:13+08:00" level=debug msg="completed keyexchange" Oct 08 23:41:13 my-player go-librespot[22397]: time="2024-10-08T23:41:13+08:00" level=debug msg="completed challenge" Oct 08 23:41:13 my-player go-librespot[22397]: time="2024-10-08T23:41:13+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:41:13 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:41:13 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:41:14 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:14 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:16 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:41:16 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 864. Oct 08 23:41:16 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:41:16 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:41:16 my-player go-librespot[22406]: Librespot-go daemon starting... Oct 08 23:41:16 my-player go-librespot[22406]: time="2024-10-08T23:41:16+08:00" level=info msg="generated new device id: d05cb40943dd71d1b6a38baa2155e3d3cc6fe0f1" Oct 08 23:41:16 my-player go-librespot[22406]: time="2024-10-08T23:41:16+08:00" level=debug msg="stored credentials not found" Oct 08 23:41:17 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:17 my-player go-librespot[22406]: time="2024-10-08T23:41:17+08:00" level=debug msg="new websocket client" Oct 08 23:41:17 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:41:17 my-player go-librespot[22406]: time="2024-10-08T23:41:17+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:41:17 my-player go-librespot[22406]: time="2024-10-08T23:41:17+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:41:17 my-player go-librespot[22406]: time="2024-10-08T23:41:17+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:41:17 my-player go-librespot[22406]: time="2024-10-08T23:41:17+08:00" level=debug msg="zeroconf server listening on port 34095" Oct 08 23:41:18 my-player go-librespot[22406]: time="2024-10-08T23:41:18+08:00" level=debug msg="obtained new client token: AABzvnHS1lawLwPsitM7G5E4vVvkKxHfPwZu22rXajSuj7C+o1vuQ4FCi7uyNJX0aPgHajKfb7661x/s3QtGq3s/whOpuPGtTYjrnwLYqRZA3jIpww6r6CfIkn1xUAXvC9yJM2zPTyhGghWwS6B1K53Z7crznzuGnpV9wZyZ00AM2e81viy6H+coByxiSAE5O3+BkaTXKwSYq3mA7ddjddAHjy8yG/Kg4602CqxFWb6ZVE7PeEmM1FCjSs9Hsbny" Oct 08 23:41:18 my-player go-librespot[22406]: time="2024-10-08T23:41:18+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:41:18 my-player go-librespot[22406]: time="2024-10-08T23:41:18+08:00" level=debug msg="completed keyexchange" Oct 08 23:41:19 my-player go-librespot[22406]: time="2024-10-08T23:41:19+08:00" level=debug msg="completed challenge" Oct 08 23:41:19 my-player go-librespot[22406]: time="2024-10-08T23:41:19+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:41:19 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:41:19 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:41:19 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:41:20 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:41:20 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:20 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:41:20 my-player volumio[6703]: (node:6703) 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: 512) Oct 08 23:41:20 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 08 23:41:20 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:20 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:20 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:20 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 08 23:41:20 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 08 23:41:20 my-player volumio[6703]: info: Discovery: Getting this device information Oct 08 23:41:20 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:20 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:20 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 08 23:41:20 my-player volumio[6703]: verbose: New Socket.io Connection to 192.168.0.20:3000 from 192.168.0.16 UA: Dart/3.4 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Oct 08 23:41:20 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:20 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:20 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 08 23:41:20 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 08 23:41:22 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:22 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:22 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:41:22 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 865. Oct 08 23:41:22 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:41:22 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:41:22 my-player go-librespot[22415]: Librespot-go daemon starting... Oct 08 23:41:22 my-player go-librespot[22415]: time="2024-10-08T23:41:22+08:00" level=info msg="generated new device id: af0807e6937ec224716923f7f179c507c244a66e" Oct 08 23:41:22 my-player go-librespot[22415]: time="2024-10-08T23:41:22+08:00" level=debug msg="stored credentials not found" Oct 08 23:41:23 my-player go-librespot[22415]: time="2024-10-08T23:41:23+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 08 23:41:23 my-player go-librespot[22415]: time="2024-10-08T23:41:23+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 08 23:41:23 my-player go-librespot[22415]: time="2024-10-08T23:41:23+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 08 23:41:23 my-player go-librespot[22415]: time="2024-10-08T23:41:23+08:00" level=debug msg="zeroconf server listening on port 35769" Oct 08 23:41:23 my-player sudo[22425]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 08 23:41:23 my-player sudo[22425]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 23:41:23 my-player sudo[22425]: pam_unix(sudo:session): session closed for user root Oct 08 23:41:23 my-player sudo[22428]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 08 23:41:23 my-player sudo[22428]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 23:41:23 my-player sudo[22428]: pam_unix(sudo:session): session closed for user root Oct 08 23:41:23 my-player volumio[6703]: verbose: New Socket.io Connection to 192.168.0.20 from 192.168.0.16 UA: Mozilla/5.0 (Linux; Android 14; 2201122G Build/UKQ1.230917.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/129.0.6668.70 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Oct 08 23:41:23 my-player sudo[22431]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 08 23:41:23 my-player sudo[22431]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 23:41:23 my-player sudo[22431]: pam_unix(sudo:session): session closed for user root Oct 08 23:41:23 my-player sudo[22434]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 08 23:41:23 my-player sudo[22434]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 23:41:23 my-player sudo[22434]: pam_unix(sudo:session): session closed for user root Oct 08 23:41:24 my-player volumio[6703]: verbose: New Socket.io Connection to 192.168.0.20 from 192.168.0.16 UA: Mozilla/5.0 (Linux; Android 14; 2201122G Build/UKQ1.230917.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/129.0.6668.70 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::volumioGetVisibleSources Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:24 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 08 23:41:24 my-player volumio[6703]: info: Received Get System Info Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 08 23:41:24 my-player volumio[6703]: info: Discovery: Getting this device information Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:24 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:24 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:24 my-player go-librespot[22415]: time="2024-10-08T23:41:24+08:00" level=debug msg="obtained new client token: AAAMabizcatPlOtCACzVY274bdvDnlBnjR5IsVc7+XjRsOvBxgL8RWGzRxgKm0b0bgIUiSfhKiN8/lnTI5TmLcO+kYluyeF7okn4/xsx/QPX1KcwINsqw/asu2SCP5DoxqoGCwEM8hyJG0feGx45gwvWWlYL177kFyiBNk1thut+usM6cAhDkdSi2yVg0KHPlCag42y1skiU3KwBy8OIhMF4cgZJ3GhriSggIcbw9aP5Vr6X6jSWgDY4I1sjvQ==" Oct 08 23:41:24 my-player volumio[6703]: info: Listing playlists Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 08 23:41:24 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 08 23:41:24 my-player go-librespot[22415]: time="2024-10-08T23:41:24+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:41:24 my-player go-librespot[22415]: time="2024-10-08T23:41:24+08:00" level=debug msg="completed keyexchange" Oct 08 23:41:24 my-player go-librespot[22415]: time="2024-10-08T23:41:24+08:00" level=debug msg="completed challenge" Oct 08 23:41:24 my-player go-librespot[22415]: time="2024-10-08T23:41:24+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:41:24 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:41:24 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 08 23:41:25 my-player volumio[6703]: info: Discovery: Getting this device information Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:25 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 08 23:41:25 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:25 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 08 23:41:25 my-player volumio[6703]: info: Received Get System Info Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 08 23:41:25 my-player volumio[6703]: info: Discovery: Getting this device information Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:25 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 08 23:41:25 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 08 23:41:28 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:41:28 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 866. Oct 08 23:41:28 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:41:28 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:41:28 my-player go-librespot[22436]: Librespot-go daemon starting... Oct 08 23:41:28 my-player go-librespot[22436]: time="2024-10-08T23:41:28+08:00" level=info msg="generated new device id: 57732e7f34183f3ac7fc08fe767029be08fb943e" Oct 08 23:41:28 my-player go-librespot[22436]: time="2024-10-08T23:41:28+08:00" level=debug msg="stored credentials not found" Oct 08 23:41:28 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:28 my-player go-librespot[22436]: time="2024-10-08T23:41:28+08:00" level=debug msg="new websocket client" Oct 08 23:41:28 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:41:28 my-player go-librespot[22436]: time="2024-10-08T23:41:28+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:41:28 my-player go-librespot[22436]: time="2024-10-08T23:41:28+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:41:28 my-player go-librespot[22436]: time="2024-10-08T23:41:28+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:41:28 my-player go-librespot[22436]: time="2024-10-08T23:41:28+08:00" level=debug msg="zeroconf server listening on port 38619" Oct 08 23:41:29 my-player volumio[6703]: info: CoreCommandRouter::volumioGetQueue Oct 08 23:41:29 my-player volumio[6703]: info: CoreStateMachine::getQueue Oct 08 23:41:29 my-player volumio[6703]: info: CorePlayQueue::getQueue Oct 08 23:41:30 my-player go-librespot[22436]: time="2024-10-08T23:41:30+08:00" level=debug msg="obtained new client token: AADV0HxADScxvnLaVkY7W86svp2bGPzVmiHeLtu7hZ3WxZYQYvxsEe/dUgD6AeMySn+z+w01CQVG8d0ABSrCmEvnwDzEVi2vx8Prbm8FUywvZiZ5sbEkGB5phZBFgUUEWcQ0cQ/47iqhnm6V9wBei+9Aaahrx4g+/PHGs7ZJ/hYt5djlc/fGbKHjShUmakNIaRfuhqmDsrH1KWyaE4Qj5FOZcgAh0MNLK8xiUKHxRrx73Hi+JBJXqIAbGck+Ebeq" Oct 08 23:41:30 my-player go-librespot[22436]: time="2024-10-08T23:41:30+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:41:30 my-player go-librespot[22436]: time="2024-10-08T23:41:30+08:00" level=debug msg="completed keyexchange" Oct 08 23:41:31 my-player go-librespot[22436]: time="2024-10-08T23:41:31+08:00" level=debug msg="completed challenge" Oct 08 23:41:31 my-player go-librespot[22436]: time="2024-10-08T23:41:31+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:41:31 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:41:31 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:41:31 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:41:31 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:41:31 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:31 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:41:31 my-player volumio[6703]: (node:6703) 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: 513) Oct 08 23:41:31 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 08 23:41:31 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:31 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:31 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:34 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 08 23:41:34 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:34 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:34 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:41:34 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 867. Oct 08 23:41:34 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:41:34 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:41:34 my-player go-librespot[22445]: Librespot-go daemon starting... Oct 08 23:41:34 my-player go-librespot[22445]: time="2024-10-08T23:41:34+08:00" level=info msg="generated new device id: bac97f7a6026509892f1b16861910c7637634ee1" Oct 08 23:41:34 my-player go-librespot[22445]: time="2024-10-08T23:41:34+08:00" level=debug msg="stored credentials not found" Oct 08 23:41:35 my-player go-librespot[22445]: time="2024-10-08T23:41:35+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 08 23:41:35 my-player go-librespot[22445]: time="2024-10-08T23:41:35+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 08 23:41:35 my-player go-librespot[22445]: time="2024-10-08T23:41:35+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 08 23:41:35 my-player go-librespot[22445]: time="2024-10-08T23:41:35+08:00" level=debug msg="zeroconf server listening on port 43425" Oct 08 23:41:36 my-player go-librespot[22445]: time="2024-10-08T23:41:36+08:00" level=debug msg="obtained new client token: AACJp0WgsgxBlMLl65t1nmbGNpNULQZNuKvlAINlCWFAgE5JJtZtHowoEIv1kADzghg3+rKfHSPd8rX9ouNleP6CUFeBGeAHNVWX3WNWWRzKEu+CeY/hqs5KLHZaqeOugXE6WYgEtpYxXkpY/aCokZ8d8XJyCCLVbenkGNhNy3VhdZKcriL9D9rHKMdNNHEMn2ncGuuzo2edqTar3DW7sLh/B+PiSrnShrq+ejEXgCVy4Fj+e5w0meQiUHNS7w==" Oct 08 23:41:36 my-player go-librespot[22445]: time="2024-10-08T23:41:36+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:41:36 my-player go-librespot[22445]: time="2024-10-08T23:41:36+08:00" level=debug msg="completed keyexchange" Oct 08 23:41:36 my-player go-librespot[22445]: time="2024-10-08T23:41:36+08:00" level=debug msg="completed challenge" Oct 08 23:41:37 my-player go-librespot[22445]: time="2024-10-08T23:41:37+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:41:37 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:41:37 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:41:37 my-player volumiologrotate[794]: ls: cannot access '/var/log/samba/log.wb-MY': No such file or directory Oct 08 23:41:37 my-player volumiologrotate[794]: ls: cannot access 'PLAYER': No such file or directory Oct 08 23:41:37 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:37 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:38 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 08 23:41:38 my-player volumio[6703]: info: CURURI: music-library/USB/DATA/Music/Eagle Oct 08 23:41:38 my-player volumio[6703]: info: Preload queue cleared Oct 08 23:41:38 my-player volumio[6703]: info: Preloading song: music-library/USB/DATA/Music/Eagle/Hotel.California.flac Oct 08 23:41:38 my-player volumio[6703]: info: Exploding uri music-library/USB/DATA/Music/Eagle/Hotel.California.flac in service mpd Oct 08 23:41:38 my-player volumio[6703]: info: ALBUMART /albumart?cacheid=665&web=Eagle/Eagle/large&path=%2Fmnt%2FUSB%2FDATA%2FMusic%2FEagle%2FHotel.California.flac&metadata=false Oct 08 23:41:38 my-player volumio[6703]: info: URI /mnt/USB/DATA/Music/Eagle/Hotel.California.flac Oct 08 23:41:40 my-player volumio[6703]: info: Preload queue cleared Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::ClearQueue Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::stop Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::updateTrackBlock Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrackBlock Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::stPlaybackTimer Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::serviceStop Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::serviceStop Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::stop Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand stop Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::clearPlayQueue Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::saveQueue Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushQueue Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::addQueueItems Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::addQueueItems Oct 08 23:41:40 my-player volumio[6703]: info: Preload queue cleared Oct 08 23:41:40 my-player volumio[6703]: info: Adding Item to queue: music-library/USB/DATA/Music/Eagle/Hotel.California.flac Oct 08 23:41:40 my-player volumio[6703]: info: Using cached record of: music-library/USB/DATA/Music/Eagle/Hotel.California.flac Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushQueue Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::saveQueue Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::updateTrackBlock Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrackBlock Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPlay Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::play index 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::stop Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::play index undefined Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::startPlaybackTimer Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::clearAddPlayTracks USB/DATA/Music/Eagle/Hotel.California.flac Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand stop Oct 08 23:41:40 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces state update: player Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand stop took 64 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::getState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand status Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand stop took 15 milliseconds Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand clear Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces state update: player Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::getState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand status Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces state update: player Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::getState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand status Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces system playlist update Oct 08 23:41:40 my-player volumio[6703]: info: Ignoring MPD Status Update Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand status took 6 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand clear took 5 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand status took 4 milliseconds Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand add "USB/DATA/Music/Eagle/Hotel.California.flac" Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseState Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::servicePushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 08 23:41:40 my-player volumio[6703]: verbose: CURRENT POSITION 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState stateService stop Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState currentStatus stop Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: No code Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:41:40 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 868. Oct 08 23:41:40 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 59ms Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces system playlist update Oct 08 23:41:40 my-player volumio[6703]: info: Ignoring MPD Status Update Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces system playlist update Oct 08 23:41:40 my-player volumio[6703]: info: Ignoring MPD Status Update Oct 08 23:41:40 my-player volumio[6703]: error: Upnp client error: Error: This socket has been ended by the other party Oct 08 23:41:40 my-player volumio[6703]: error: updateQueue error: null Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces system playlist update Oct 08 23:41:40 my-player volumio[6703]: info: Ignoring MPD Status Update Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand status took 67 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 67ms Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand playlistinfo took 63 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand add "USB/DATA/Music/Eagle/Hotel.California.flac" took 62 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 11ms Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 10ms Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseTrackInfo Oct 08 23:41:40 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand play Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::servicePushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player go-librespot[22500]: Librespot-go daemon starting... Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 08 23:41:40 my-player volumio[6703]: verbose: CURRENT POSITION 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState stateService stop Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState currentStatus stop Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: No code Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Oct 08 23:41:40 my-player go-librespot[22500]: time="2024-10-08T23:41:40+08:00" level=info msg="generated new device id: 9e01deab5a945540714bd7cb1820bdbd3f46e9fb" Oct 08 23:41:40 my-player go-librespot[22500]: time="2024-10-08T23:41:40+08:00" level=debug msg="stored credentials not found" Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 126ms Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 132ms Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces system playlist update Oct 08 23:41:40 my-player volumio[6703]: info: Ignoring MPD Status Update Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces system playlist update Oct 08 23:41:40 my-player volumio[6703]: info: Ignoring MPD Status Update Oct 08 23:41:40 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:40 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:40 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:40 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:40 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:40 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:40 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces state update: player Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 78ms Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand play took 72 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::getState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand status Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 19ms Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 18ms Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces state update: player Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::getState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand status Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces state update: player Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::getState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand status Oct 08 23:41:40 my-player go-librespot[22500]: time="2024-10-08T23:41:40+08:00" level=debug msg="new websocket client" Oct 08 23:41:40 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand status took 193 milliseconds Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces state update: player Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::getState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand status Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand status took 204 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand status took 203 milliseconds Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces state update: player Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::getState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand status Oct 08 23:41:40 my-player volumio[6703]: info: Oct 08 23:41:40 my-player volumio[6703]: ---------------------------- MPD announces state update: player Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::getState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand status Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand playlistinfo took 8 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand status took 8 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand playlistinfo took 7 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand playlistinfo took 6 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand status took 4 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand status took 3 milliseconds Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseTrackInfo Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseTrackInfo Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseTrackInfo Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseState Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::servicePushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":433,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Hotel California","artist":"Eagle","album":"Eagle","uri":"USB/DATA/Music/Eagle/Hotel.California.flac","trackType":"flac"} Oct 08 23:41:40 my-player volumio[6703]: verbose: CURRENT POSITION 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState stateService play Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState currentStatus stop Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::servicePushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":433,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"830 Kbps","isStreaming":false,"title":"Hotel California","artist":"Eagle","album":"Eagle","uri":"USB/DATA/Music/Eagle/Hotel.California.flac","trackType":"flac"} Oct 08 23:41:40 my-player volumio[6703]: verbose: CURRENT POSITION 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState stateService play Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState currentStatus play Oct 08 23:41:40 my-player volumio[6703]: info: Received an update from plugin. extracting info from payload Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::servicePushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: verbose: STATE SERVICE {"status":"play","position":0,"seek":591,"duration":433,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"809 Kbps","isStreaming":false,"title":"Hotel California","artist":"Eagle","album":"Eagle","uri":"USB/DATA/Music/Eagle/Hotel.California.flac","trackType":"flac"} Oct 08 23:41:40 my-player volumio[6703]: verbose: CURRENT POSITION 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState stateService play Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState currentStatus play Oct 08 23:41:40 my-player volumio[6703]: info: Received an update from plugin. extracting info from payload Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 232ms Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 239ms Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 239ms Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand playlistinfo took 27 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand playlistinfo took 27 milliseconds Oct 08 23:41:40 my-player volumio[6703]: info: sendMpdCommand playlistinfo took 27 milliseconds Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseTrackInfo Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseTrackInfo Oct 08 23:41:40 my-player volumio[6703]: verbose: ControllerMpd::parseTrackInfo Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::servicePushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: verbose: STATE SERVICE {"status":"play","position":0,"seek":842,"duration":433,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"813 Kbps","isStreaming":false,"title":"Hotel California","artist":"Eagle","album":"Eagle","uri":"USB/DATA/Music/Eagle/Hotel.California.flac","trackType":"flac"} Oct 08 23:41:40 my-player volumio[6703]: verbose: CURRENT POSITION 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState stateService play Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState currentStatus play Oct 08 23:41:40 my-player volumio[6703]: info: Received an update from plugin. extracting info from payload Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::servicePushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: verbose: STATE SERVICE {"status":"play","position":0,"seek":956,"duration":433,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"806 Kbps","isStreaming":false,"title":"Hotel California","artist":"Eagle","album":"Eagle","uri":"USB/DATA/Music/Eagle/Hotel.California.flac","trackType":"flac"} Oct 08 23:41:40 my-player volumio[6703]: verbose: CURRENT POSITION 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState stateService play Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState currentStatus play Oct 08 23:41:40 my-player volumio[6703]: info: Received an update from plugin. extracting info from payload Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: ControllerMpd::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::servicePushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: verbose: STATE SERVICE {"status":"play","position":0,"seek":956,"duration":433,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"806 Kbps","isStreaming":false,"title":"Hotel California","artist":"Eagle","album":"Eagle","uri":"USB/DATA/Music/Eagle/Hotel.California.flac","trackType":"flac"} Oct 08 23:41:40 my-player volumio[6703]: verbose: CURRENT POSITION 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState stateService play Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::syncState currentStatus play Oct 08 23:41:40 my-player volumio[6703]: info: Received an update from plugin. extracting info from payload Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: CoreStateMachine::pushState Oct 08 23:41:40 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:40 my-player volumio[6703]: info: CoreCommandRouter::volumioPushState Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 74ms Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 71ms Oct 08 23:41:40 my-player volumio[6703]: info: ------------------------------ 70ms Oct 08 23:41:40 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:40 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:41 my-player go-librespot[22500]: time="2024-10-08T23:41:41+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:41:41 my-player go-librespot[22500]: time="2024-10-08T23:41:41+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:41:41 my-player go-librespot[22500]: time="2024-10-08T23:41:41+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:41:41 my-player go-librespot[22500]: time="2024-10-08T23:41:41+08:00" level=debug msg="zeroconf server listening on port 36109" Oct 08 23:41:41 my-player go-librespot[22500]: time="2024-10-08T23:41:41+08:00" level=debug msg="obtained new client token: AAAfSKrQkT1K3BDyCVARMJCMeBPJE/672375Tiic2hXWSyPrAD+6o7zYixVDe6rDNtbSlIWLNONf1iWY5FbEqSyIjAJJiTo5A2p5+CB1OqoB9EKCUBIWDPNjB5TZ93oca758VqRgoR8+3Gx6gEvA5eMmiuwcqPl6njP5gdqmeofSbHqDpmKtMxu35iZxTO/XQUbRT2Z8F8fr65e3mYM4JJdonfu8AvogGdRedE0fvmRJbu+aI0XOeqpb7YgDIoSZ" Oct 08 23:41:41 my-player go-librespot[22500]: time="2024-10-08T23:41:41+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:41:42 my-player go-librespot[22500]: time="2024-10-08T23:41:42+08:00" level=debug msg="completed keyexchange" Oct 08 23:41:42 my-player go-librespot[22500]: time="2024-10-08T23:41:42+08:00" level=debug msg="completed challenge" Oct 08 23:41:42 my-player go-librespot[22500]: time="2024-10-08T23:41:42+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:41:42 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:41:42 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:41:42 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:41:43 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:41:43 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:43 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:41:43 my-player volumio[6703]: (node:6703) 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: 514) Oct 08 23:41:43 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 08 23:41:43 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:43 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:43 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:43 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 08 23:41:43 my-player volumio[6703]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 08 23:41:43 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 08 23:41:43 my-player volumio[6703]: info: Received Get System Version Oct 08 23:41:43 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 08 23:41:43 my-player volumio[6703]: info: Received Get System Info Oct 08 23:41:43 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 08 23:41:43 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 08 23:41:43 my-player volumio[6703]: info: Discovery: Getting this device information Oct 08 23:41:43 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:43 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:43 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 08 23:41:45 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:45 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:45 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:41:45 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 869. Oct 08 23:41:45 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:41:45 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:41:45 my-player go-librespot[22528]: Librespot-go daemon starting... Oct 08 23:41:45 my-player go-librespot[22528]: time="2024-10-08T23:41:45+08:00" level=info msg="generated new device id: ff96356d8e3d9374206d993631822fc4692cc9fb" Oct 08 23:41:45 my-player go-librespot[22528]: time="2024-10-08T23:41:45+08:00" level=debug msg="stored credentials not found" Oct 08 23:41:46 my-player go-librespot[22528]: time="2024-10-08T23:41:46+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 08 23:41:46 my-player go-librespot[22528]: time="2024-10-08T23:41:46+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 08 23:41:46 my-player go-librespot[22528]: time="2024-10-08T23:41:46+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 08 23:41:46 my-player go-librespot[22528]: time="2024-10-08T23:41:46+08:00" level=debug msg="zeroconf server listening on port 37845" Oct 08 23:41:47 my-player go-librespot[22528]: time="2024-10-08T23:41:47+08:00" level=debug msg="obtained new client token: AAC7UW6+TdQLu1HjDg09WtwSNZ/AZ2gR5gJ/4ND+yXxRTRRIVw+IcPb85T+HrEUx3ImUmDZfIfVDY4kKu+Rp/HIfFeusxX8TlsUJyEBdXUTZZgyfXQw3uC/sZxaNRnslUwlnLlE4wCKgksBjW9azqImTorX2RfT/ZitOs/ba82BVuXCCFsxmKuNVHULWhsggx8awy0+qeqMcjyIc07t9XSheh6N2i4uRISg820ZZHjJs4zG9Sbr0Kjll+VqJdR5v" Oct 08 23:41:47 my-player go-librespot[22528]: time="2024-10-08T23:41:47+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:41:47 my-player go-librespot[22528]: time="2024-10-08T23:41:47+08:00" level=debug msg="completed keyexchange" Oct 08 23:41:48 my-player go-librespot[22528]: time="2024-10-08T23:41:48+08:00" level=debug msg="completed challenge" Oct 08 23:41:48 my-player go-librespot[22528]: time="2024-10-08T23:41:48+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:41:48 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:41:48 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:41:48 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:48 my-player volumio[6703]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:50 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 08 23:41:50 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 08 23:41:50 my-player volumio[6703]: info: Discovery: Getting this device information Oct 08 23:41:50 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:50 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:50 my-player volumio[6703]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 08 23:41:51 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 08 23:41:51 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 870. Oct 08 23:41:51 my-player systemd[1]: Stopped go-librespot Daemon. Oct 08 23:41:51 my-player systemd[1]: Started go-librespot Daemon. Oct 08 23:41:51 my-player go-librespot[22547]: Librespot-go daemon starting... Oct 08 23:41:51 my-player go-librespot[22547]: time="2024-10-08T23:41:51+08:00" level=info msg="generated new device id: 78915d77dd06d87e962c4968780343dfc2b99d95" Oct 08 23:41:51 my-player go-librespot[22547]: time="2024-10-08T23:41:51+08:00" level=debug msg="stored credentials not found" Oct 08 23:41:51 my-player volumio[6703]: info: Initializing connection to go-librespot Websocket Oct 08 23:41:51 my-player go-librespot[22547]: time="2024-10-08T23:41:51+08:00" level=debug msg="new websocket client" Oct 08 23:41:51 my-player volumio[6703]: info: Connection to go-librespot Websocket established Oct 08 23:41:52 my-player go-librespot[22547]: time="2024-10-08T23:41:52+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 08 23:41:52 my-player go-librespot[22547]: time="2024-10-08T23:41:52+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 08 23:41:52 my-player go-librespot[22547]: time="2024-10-08T23:41:52+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 08 23:41:52 my-player go-librespot[22547]: time="2024-10-08T23:41:52+08:00" level=debug msg="zeroconf server listening on port 43893" Oct 08 23:41:52 my-player go-librespot[22547]: time="2024-10-08T23:41:52+08:00" level=debug msg="obtained new client token: AAAqEXj2asEZ2XVIWeNqVEs/QGZy3jETu04h9mMbRqX+Dn2hxwvC5tzqFIvVV4pDW8OvatqqD1ux+OqqXQO4y1ioxPopOagdk1Sr3/I82X/tBq8DUx+c+TmoAVTHXPPWAa5/NpZf1fv9qvwGl91VWiEAcGdBovuP8aHdY4WPT+P3s1N79CZsO3q3fUFmw6Clde7YWhQqUInLxgpXtjvzK1rkI6WIQJ85Uxr9QwMmV6sbM4ShE6wn1dyPYawSCz+Y" Oct 08 23:41:53 my-player go-librespot[22547]: time="2024-10-08T23:41:53+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 08 23:41:53 my-player go-librespot[22547]: time="2024-10-08T23:41:53+08:00" level=debug msg="completed keyexchange" Oct 08 23:41:53 my-player go-librespot[22547]: time="2024-10-08T23:41:53+08:00" level=debug msg="completed challenge" Oct 08 23:41:53 my-player go-librespot[22547]: time="2024-10-08T23:41:53+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Oct 08 23:41:53 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 08 23:41:53 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 08 23:41:53 my-player volumio[6703]: info: Connection to go-librespot Websocket closed Oct 08 23:41:54 my-player volumio[6703]: info: Getting Spotify volume Oct 08 23:41:54 my-player volumio[6703]: (node:6703) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 08 23:41:54 my-player volumio[6703]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 08 23:41:54 my-player volumio[6703]: (node:6703) 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: 515) Oct 08 23:41:54 my-player volumio[6703]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 08 23:41:54 my-player volumio[6703]: info: CoreCommandRouter::volumioGetState Oct 08 23:41:54 my-player volumio[6703]: info: CorePlayQueue::getTrack 0 Oct 08 23:41:54 my-player volumio[6703]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Oct 08 23:41:55 my-player volumio[6703]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 08 23:41:55 my-player volumio[6703]: [t [Error]: A network error (such as timeout, interrupted connection or unreachable host) has occurred.] { Oct 08 23:41:55 my-player volumio[6703]: code: 'auth/network-request-failed', Oct 08 23:41:55 my-player volumio[6703]: a: null Oct 08 23:41:55 my-player volumio[6703]: } Oct 08 23:41:55 my-player volumio[6703]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 08 23:41:56 my-player sudo[22574]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-08 23:40 Oct 08 23:41:56 my-player sudo[22574]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:33:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ee834e1c2a28de3c5d8c48611ecf1167"