-- Logs begin at Mon 2024-11-25 15:05:49 EST, end at Mon 2024-11-25 16:18:50 EST. -- Nov 25 16:17:01 ross-5060a nmbd[762]: [2024/11/25 16:17:01.929973, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Nov 25 16:17:01 ross-5060a nmbd[762]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.50.45 for name WORKGROUP<1d>. Nov 25 16:17:01 ross-5060a nmbd[762]: This response was from IP 192.168.50.207, reporting an IP address of 192.168.50.207. Nov 25 16:17:02 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:02 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6194. Nov 25 16:17:02 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:02 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:02 ross-5060a go-librespot[9318]: Librespot-go daemon starting... Nov 25 16:17:02 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:02-05:00" level=info msg="generated new device id: 0059d9e7bb8997b097af8848d686118ca0e1c472" Nov 25 16:17:02 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:02-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:02 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:02 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:02-05:00" level=debug msg="new websocket client" Nov 25 16:17:02 ross-5060a volumio[981]: info: Connection to go-librespot Websocket established Nov 25 16:17:03 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:03-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:17:03 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:03-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:17:03 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:03-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:17:03 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:03-05:00" level=debug msg="zeroconf server listening on port 34397" Nov 25 16:17:03 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:03-05:00" level=debug msg="obtained new client token: AABAdSmbk5pAuwcHoQUIzmEcASNe1UQ7IdPKTevTIyU+ndhj6qyyXWiwc1nWmDhZrhif4Kcp3tieOLm4H3h44SBmFRYNQpZke0+mS0efQ4VcxzWkK9NqQCFwjDbVX2ND6nca2BUsVpIBTJkX5fHcvCGbURR4eRh1kP6gtP9oxSPr2xYNlpcGD7lxUf38AukFpXghY3gor+SohhuMc9vQQ22lZC5ypbIVAtIj3sXJJ9QaJBKSLrtRjNp5" Nov 25 16:17:03 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:03-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:03 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:03-05:00" level=debug msg="completed challenge" Nov 25 16:17:03 ross-5060a go-librespot[9318]: time="2024-11-25T16:17:03-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:03 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:03 ross-5060a volumio[981]: info: Connection to go-librespot Websocket closed Nov 25 16:17:03 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:05 ross-5060a volumio[981]: info: Getting Spotify volume Nov 25 16:17:05 ross-5060a volumio[981]: (node:981) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:05 ross-5060a volumio[981]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 25 16:17:05 ross-5060a volumio[981]: (node:981) 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: 2238) Nov 25 16:17:05 ross-5060a volumio[981]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 25 16:17:05 ross-5060a volumio[981]: info: CoreCommandRouter::volumioGetState Nov 25 16:17:05 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:17:05 ross-5060a volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Nov 25 16:17:06 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:06 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:07 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:07 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6195. Nov 25 16:17:07 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:07 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:07 ross-5060a go-librespot[9333]: Librespot-go daemon starting... Nov 25 16:17:07 ross-5060a go-librespot[9333]: time="2024-11-25T16:17:07-05:00" level=info msg="generated new device id: 2990ad4388a36998c5d7e8b909bfa2375fc792db" Nov 25 16:17:07 ross-5060a go-librespot[9333]: time="2024-11-25T16:17:07-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:07 ross-5060a go-librespot[9333]: time="2024-11-25T16:17:07-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:17:07 ross-5060a go-librespot[9333]: time="2024-11-25T16:17:07-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:17:07 ross-5060a go-librespot[9333]: time="2024-11-25T16:17:07-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:17:07 ross-5060a go-librespot[9333]: time="2024-11-25T16:17:07-05:00" level=debug msg="zeroconf server listening on port 37111" Nov 25 16:17:07 ross-5060a go-librespot[9333]: time="2024-11-25T16:17:07-05:00" level=debug msg="obtained new client token: AACJx4egNoaiAoYdzl1rf18Iyqb23m7A8u26rvULjRdqG2mH/iTgoJHG3td4s6qy1b/zXDLiv3NsPultuQj6cvbNg/qugHWZ4My/O8/MT7vPpfV5aqj16hJQUC71wQZhmK3/Wa9E5ZAxVbkpMEIMjR8hSAKVBdkzxXVNqn0LBiR6TAx4CpdnkY6HK4KoMsOYQEehJnKLRh0Td8L9y81YRmiPndoFQIUVrXRdYXIZ2sv52LMW6YEtk11qacA=" Nov 25 16:17:07 ross-5060a go-librespot[9333]: time="2024-11-25T16:17:07-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:08 ross-5060a go-librespot[9333]: time="2024-11-25T16:17:08-05:00" level=debug msg="completed challenge" Nov 25 16:17:08 ross-5060a go-librespot[9333]: time="2024-11-25T16:17:08-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:08 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:08 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:09 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:09 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:11 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:11 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6196. Nov 25 16:17:11 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:11 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:11 ross-5060a go-librespot[9361]: Librespot-go daemon starting... Nov 25 16:17:11 ross-5060a go-librespot[9361]: time="2024-11-25T16:17:11-05:00" level=info msg="generated new device id: fa379975ee709e475ac1cc597bbdc2c07ee8be04" Nov 25 16:17:11 ross-5060a go-librespot[9361]: time="2024-11-25T16:17:11-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:11 ross-5060a go-librespot[9361]: time="2024-11-25T16:17:11-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 16:17:11 ross-5060a go-librespot[9361]: time="2024-11-25T16:17:11-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 25 16:17:11 ross-5060a go-librespot[9361]: time="2024-11-25T16:17:11-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 25 16:17:11 ross-5060a go-librespot[9361]: time="2024-11-25T16:17:11-05:00" level=debug msg="zeroconf server listening on port 41307" Nov 25 16:17:12 ross-5060a go-librespot[9361]: time="2024-11-25T16:17:12-05:00" level=debug msg="obtained new client token: AABYrlBBugkSyM25NfExswnEu+Tf/bB5ycy4mwFCaWrHP1GuKPP7PPBo1/lww2U+F0CEVWKYiZdh3t6yx0263bfo9INZ+VDPCV9fBx1vIYy/IjsXg+ATjEJ32YFO9KVN9N9+iCFjMrHDLl4+3eZU/z1IH93u4qeuw5G3CncFplntGlmckEUJ05SYsDkTlhPNPOKsJ2xKcn0752s+AWIGqwDtmms9O9lZSnWTyBcsQoBVdfpzSofXMjbG" Nov 25 16:17:12 ross-5060a go-librespot[9361]: time="2024-11-25T16:17:12-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:12 ross-5060a go-librespot[9361]: time="2024-11-25T16:17:12-05:00" level=debug msg="completed challenge" Nov 25 16:17:12 ross-5060a go-librespot[9361]: time="2024-11-25T16:17:12-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:12 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:12 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:12 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:12 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:15 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:15 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:16 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:16 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6197. Nov 25 16:17:16 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:16 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:16 ross-5060a go-librespot[9377]: Librespot-go daemon starting... Nov 25 16:17:16 ross-5060a go-librespot[9377]: time="2024-11-25T16:17:16-05:00" level=info msg="generated new device id: 06d6acefb2e61e71fcd04e3b907a136ab8be432c" Nov 25 16:17:16 ross-5060a go-librespot[9377]: time="2024-11-25T16:17:16-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:16 ross-5060a go-librespot[9377]: time="2024-11-25T16:17:16-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:17:16 ross-5060a go-librespot[9377]: time="2024-11-25T16:17:16-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:17:16 ross-5060a go-librespot[9377]: time="2024-11-25T16:17:16-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:17:16 ross-5060a go-librespot[9377]: time="2024-11-25T16:17:16-05:00" level=debug msg="zeroconf server listening on port 39435" Nov 25 16:17:16 ross-5060a go-librespot[9377]: time="2024-11-25T16:17:16-05:00" level=debug msg="obtained new client token: AABkq40+LFoL20y+8qtAsVRRxNId7SvryrDh1Cxi4cx9SunS0rIKNz4IbLuTj9E6yhdQ3iqLfHSCAf34tBjz80M5FQ7BxoNK5/eOoDGP/PkSlo/1Dhx9ZH1IUiJ8Vx0+69e8cFq+myXLeCFBX9e9vvSgVsDlQBf7T75vj3Jk/Mm/+UP3dJaC1ERDtWpPwKaA5EQ7k5B1eyiu8Q0b0wmSWuBYy5tf2KiwZJULOYnxOBUBpPtcT9G7VFhWC+U=" Nov 25 16:17:16 ross-5060a go-librespot[9377]: time="2024-11-25T16:17:16-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:17 ross-5060a go-librespot[9377]: time="2024-11-25T16:17:17-05:00" level=debug msg="completed challenge" Nov 25 16:17:17 ross-5060a go-librespot[9377]: time="2024-11-25T16:17:17-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:17 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:17 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:18 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:18 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:20 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:20 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6198. Nov 25 16:17:20 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:20 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:20 ross-5060a go-librespot[9403]: Librespot-go daemon starting... Nov 25 16:17:20 ross-5060a go-librespot[9403]: time="2024-11-25T16:17:20-05:00" level=info msg="generated new device id: da1605e2334bf4ba32893f7b6786a6b07e7eb469" Nov 25 16:17:20 ross-5060a go-librespot[9403]: time="2024-11-25T16:17:20-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:20 ross-5060a go-librespot[9403]: time="2024-11-25T16:17:20-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:17:20 ross-5060a go-librespot[9403]: time="2024-11-25T16:17:20-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:17:20 ross-5060a go-librespot[9403]: time="2024-11-25T16:17:20-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:17:20 ross-5060a go-librespot[9403]: time="2024-11-25T16:17:20-05:00" level=debug msg="zeroconf server listening on port 40573" Nov 25 16:17:21 ross-5060a go-librespot[9403]: time="2024-11-25T16:17:21-05:00" level=debug msg="obtained new client token: AABFmzhf289sIYWB2mY+ju3RHz5Q9dE28X8rTPLNIjaA6RV2I+6w2px7rY9g9gMy3eP152I5NVrYbBuTzHoRfMfVD5OD/i1ZtUEwaj79EsMxfuuC3mvKVnAyoG9sxAc3IhIKglWpIQfthxvk2da8shVowzbsTzS4+qUbgwe143F/BO1CGe9Da8trzpHAu+MU55K/bWAu/eweFSawz86LZH6d7w9hDA86WQr/aQaixM6/hkbsfZA+kphS" Nov 25 16:17:21 ross-5060a go-librespot[9403]: time="2024-11-25T16:17:21-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:21 ross-5060a go-librespot[9403]: time="2024-11-25T16:17:21-05:00" level=debug msg="completed challenge" Nov 25 16:17:21 ross-5060a go-librespot[9403]: time="2024-11-25T16:17:21-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:21 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:21 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:21 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:21 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:24 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:24 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6199. Nov 25 16:17:24 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:24 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:24 ross-5060a go-librespot[9416]: Librespot-go daemon starting... Nov 25 16:17:24 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:24-05:00" level=info msg="generated new device id: e4c913b577f8d961ce9375b7bdb134b50681828b" Nov 25 16:17:24 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:24-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:24 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:24 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:24-05:00" level=debug msg="new websocket client" Nov 25 16:17:24 ross-5060a volumio[981]: info: Connection to go-librespot Websocket established Nov 25 16:17:25 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:25-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:17:25 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:25-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:17:25 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:25-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:17:25 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:25-05:00" level=debug msg="zeroconf server listening on port 40343" Nov 25 16:17:25 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:25-05:00" level=debug msg="obtained new client token: AADLSqEttqm2MELb3kk175+TRoOruVP7wMiKuwZYXI1GHi65hLuPLsnX1+DrAr/+aoYh4UW43U1s3u2qK7SsP18sx9KERw8sOuOtisHOeT4GEd4xMh8cTTte59GN8quITeBhsg4rgfQAxOiu+ZQEkDK0wCzZud1AqJDeDdlfxygOQxYxnOA1isvIcfIPAwY8RuYBQKyFvUOw/vADHY6sfxs32NJIWlIBF8zZu0xLwwvzT7tXaBF6a13N4KQ=" Nov 25 16:17:25 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:25-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:26 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:26-05:00" level=debug msg="completed challenge" Nov 25 16:17:26 ross-5060a go-librespot[9416]: time="2024-11-25T16:17:26-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:26 ross-5060a volumio[981]: info: Connection to go-librespot Websocket closed Nov 25 16:17:26 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:26 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:27 ross-5060a volumio[981]: info: Getting Spotify volume Nov 25 16:17:28 ross-5060a volumio[981]: (node:981) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:28 ross-5060a volumio[981]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 25 16:17:28 ross-5060a volumio[981]: (node:981) 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: 2239) Nov 25 16:17:28 ross-5060a volumio[981]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 25 16:17:28 ross-5060a volumio[981]: info: CoreCommandRouter::volumioGetState Nov 25 16:17:28 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:17:28 ross-5060a volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Nov 25 16:17:29 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:29 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:29 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:29 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6200. Nov 25 16:17:29 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:29 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:29 ross-5060a go-librespot[9432]: Librespot-go daemon starting... Nov 25 16:17:29 ross-5060a go-librespot[9432]: time="2024-11-25T16:17:29-05:00" level=info msg="generated new device id: 2cbf81b9794de47536d27d78a48687531a47149d" Nov 25 16:17:29 ross-5060a go-librespot[9432]: time="2024-11-25T16:17:29-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:29 ross-5060a go-librespot[9432]: time="2024-11-25T16:17:29-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:17:29 ross-5060a go-librespot[9432]: time="2024-11-25T16:17:29-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:17:29 ross-5060a go-librespot[9432]: time="2024-11-25T16:17:29-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:17:29 ross-5060a go-librespot[9432]: time="2024-11-25T16:17:29-05:00" level=debug msg="zeroconf server listening on port 34749" Nov 25 16:17:29 ross-5060a go-librespot[9432]: time="2024-11-25T16:17:29-05:00" level=debug msg="obtained new client token: AADrYryBCk6Hq8mEDpO0LQBfUs2QBNPzH76veZPysoCNYlPrxZOfAli+tK2YCoXggkY3aWpX9wRaoXxgK1BMTfZ2b2F2J5uVeDN7yshh/gE9TdSdwyfo35jUti37VK6SHal19lBmBRT/HrwLpy91NxRUPlQYrOt+89PWDa1ODfSGxgl29xXHputoTv9o4kyN50NPcu5umqduaF0iIMpIu3XLmqGsmSRvGIVHt3DSTTwAarYWnTY6CKH9rcQ=" Nov 25 16:17:29 ross-5060a go-librespot[9432]: time="2024-11-25T16:17:29-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:30 ross-5060a go-librespot[9432]: time="2024-11-25T16:17:30-05:00" level=debug msg="completed challenge" Nov 25 16:17:30 ross-5060a go-librespot[9432]: time="2024-11-25T16:17:30-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:30 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:30 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:30 ross-5060a volumiologrotate[445]: ls: cannot access '/var/log/samba/log.wb-ROSS': No such file or directory Nov 25 16:17:30 ross-5060a volumiologrotate[445]: ls: cannot access '5060A': No such file or directory Nov 25 16:17:32 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:32 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:33 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:33 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6201. Nov 25 16:17:33 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:33 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:33 ross-5060a go-librespot[9499]: Librespot-go daemon starting... Nov 25 16:17:33 ross-5060a go-librespot[9499]: time="2024-11-25T16:17:33-05:00" level=info msg="generated new device id: beefe91bc47dc299fe7d78034a2174fd483b5683" Nov 25 16:17:33 ross-5060a go-librespot[9499]: time="2024-11-25T16:17:33-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:33 ross-5060a go-librespot[9499]: time="2024-11-25T16:17:33-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:17:33 ross-5060a go-librespot[9499]: time="2024-11-25T16:17:33-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:17:33 ross-5060a go-librespot[9499]: time="2024-11-25T16:17:33-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:17:33 ross-5060a go-librespot[9499]: time="2024-11-25T16:17:33-05:00" level=debug msg="zeroconf server listening on port 44135" Nov 25 16:17:34 ross-5060a go-librespot[9499]: time="2024-11-25T16:17:34-05:00" level=debug msg="obtained new client token: AACYWmWaLzQhYI3YMLlaj7qEo83AVwnNyxWXE0M1m9rIYnHJSH4skzWpajtYKofkRYS9AAOtJMx4Wn1DNUY/i/z2Xp36yDkrI72lZ79B72gV0Xv9P0jmyfN/45mfffgkZ2L1xh0g6ZwGwA/SXtx3Bw77DcwHee0H0KDB7L/xCDggAUTb6f10qWnBn3Cr40JA3qcmDdTGVsKaG8GILqbpyhIrafbDSYI1803sUzxIUFC2T+6TInggEqvp" Nov 25 16:17:34 ross-5060a go-librespot[9499]: time="2024-11-25T16:17:34-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:34 ross-5060a go-librespot[9499]: time="2024-11-25T16:17:34-05:00" level=debug msg="completed challenge" Nov 25 16:17:34 ross-5060a go-librespot[9499]: time="2024-11-25T16:17:34-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:34 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:34 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:35 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:35 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:37 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:37 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6202. Nov 25 16:17:37 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:37 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:37 ross-5060a go-librespot[9514]: Librespot-go daemon starting... Nov 25 16:17:37 ross-5060a go-librespot[9514]: time="2024-11-25T16:17:37-05:00" level=info msg="generated new device id: 67713d0c2d9d2eac1255c5206af77ae5945e9df7" Nov 25 16:17:37 ross-5060a go-librespot[9514]: time="2024-11-25T16:17:37-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:38 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:38 ross-5060a go-librespot[9514]: time="2024-11-25T16:17:38-05:00" level=debug msg="new websocket client" Nov 25 16:17:38 ross-5060a volumio[981]: info: Connection to go-librespot Websocket established Nov 25 16:17:38 ross-5060a go-librespot[9514]: time="2024-11-25T16:17:38-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:17:38 ross-5060a go-librespot[9514]: time="2024-11-25T16:17:38-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:17:38 ross-5060a go-librespot[9514]: time="2024-11-25T16:17:38-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:17:38 ross-5060a go-librespot[9514]: time="2024-11-25T16:17:38-05:00" level=debug msg="zeroconf server listening on port 39279" Nov 25 16:17:38 ross-5060a go-librespot[9514]: time="2024-11-25T16:17:38-05:00" level=debug msg="obtained new client token: AAC/Ld7X1Co6dEqkay2xoYQwo3sv89fexw4LZi3YdACu4BNI77ivrlr1G3SeA1i4X0mEql7o0Bp6X7FsCSzU/hPFTrEtZzQuB7kMehEdotWm0jjOD6hiHjXJ1mKvJaK3NGGGdgqZNckqsfgtzMg5OglZ2EAnoC6RTiNR8AcSMYfggaaaNyMLSLr78VJCmTXHMghdLAN6dUexe7iCngjpM75G0v0N/S5/489/mdDkKBKoKfr/zDMpZ+JhyAM=" Nov 25 16:17:38 ross-5060a go-librespot[9514]: time="2024-11-25T16:17:38-05:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 34.158.255.62:4070: connect: connection refused" Nov 25 16:17:38 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:38 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:38 ross-5060a volumio[981]: info: Connection to go-librespot Websocket closed Nov 25 16:17:41 ross-5060a volumio[981]: info: Getting Spotify volume Nov 25 16:17:41 ross-5060a volumio[981]: (node:981) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:41 ross-5060a volumio[981]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 25 16:17:41 ross-5060a volumio[981]: (node:981) 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: 2240) Nov 25 16:17:41 ross-5060a volumio[981]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 25 16:17:41 ross-5060a volumio[981]: info: CoreCommandRouter::volumioGetState Nov 25 16:17:41 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:17:41 ross-5060a volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Nov 25 16:17:41 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:41 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:41 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:41 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6203. Nov 25 16:17:41 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:41 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:41 ross-5060a go-librespot[9540]: Librespot-go daemon starting... Nov 25 16:17:41 ross-5060a go-librespot[9540]: time="2024-11-25T16:17:41-05:00" level=info msg="generated new device id: 2bb24e0735ad66cb48bb34a8c04f43477edc77b7" Nov 25 16:17:41 ross-5060a go-librespot[9540]: time="2024-11-25T16:17:41-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:41 ross-5060a go-librespot[9540]: time="2024-11-25T16:17:41-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 16:17:41 ross-5060a go-librespot[9540]: time="2024-11-25T16:17:41-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 25 16:17:41 ross-5060a go-librespot[9540]: time="2024-11-25T16:17:41-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 25 16:17:41 ross-5060a go-librespot[9540]: time="2024-11-25T16:17:41-05:00" level=debug msg="zeroconf server listening on port 40695" Nov 25 16:17:42 ross-5060a go-librespot[9540]: time="2024-11-25T16:17:42-05:00" level=debug msg="obtained new client token: AAAnk54S6eC9wUorPiISx1CPL52Xlmzw+Bu+HeUL0pKCoQSGpsq1lLZKnrXiziBJ7v9EltO919Ad2J2Ns1LuDVcob65buFsIScvyz/tNdupagkqZO1BDIYF8QJuLK8y+CG+OIMylt5t9YeICXEMKm3KWQcX6eQTBkgnRk4mM+dkDFsXJlCFc8uEUUyc1LID4/Iu66isG4tjWqdryb/P/m5guPU/UteTAUjp7URVxLmzR3RKn0uZSRiZS" Nov 25 16:17:42 ross-5060a go-librespot[9540]: time="2024-11-25T16:17:42-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:42 ross-5060a go-librespot[9540]: time="2024-11-25T16:17:42-05:00" level=debug msg="completed challenge" Nov 25 16:17:42 ross-5060a go-librespot[9540]: time="2024-11-25T16:17:42-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:42 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:42 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:44 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:44 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:45 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:45 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6204. Nov 25 16:17:45 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:45 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:45 ross-5060a go-librespot[9556]: Librespot-go daemon starting... Nov 25 16:17:45 ross-5060a go-librespot[9556]: time="2024-11-25T16:17:45-05:00" level=info msg="generated new device id: 04c8672f9639b73c3469f29c714c5b4e224ad1ac" Nov 25 16:17:45 ross-5060a go-librespot[9556]: time="2024-11-25T16:17:45-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:46 ross-5060a go-librespot[9556]: time="2024-11-25T16:17:46-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:17:46 ross-5060a go-librespot[9556]: time="2024-11-25T16:17:46-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:17:46 ross-5060a go-librespot[9556]: time="2024-11-25T16:17:46-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:17:46 ross-5060a go-librespot[9556]: time="2024-11-25T16:17:46-05:00" level=debug msg="zeroconf server listening on port 34291" Nov 25 16:17:46 ross-5060a go-librespot[9556]: time="2024-11-25T16:17:46-05:00" level=debug msg="obtained new client token: AABigSCNUiErC0wEKzy3ItmtbE9Z6SRDUYATp9yIoqXzlLRPIlh241Beg23/F6B8HwXNj7dlKHV+4JP1MoKt44Uqq54CkYX9b5PrBOxFmtbX9l/8mWckP+fjDaKcPNns9Ljct+U4IdCGm71eHMbrGlHkx3XFGvtt7wEisaZkBUZOeuealuii4wzsm5/Lfdy1Y6QT/Z+YLqazqHtV9RFkFl9wYpychgcp5hPHBIMHvQd+OmzhGUcvizr7jnM=" Nov 25 16:17:46 ross-5060a go-librespot[9556]: time="2024-11-25T16:17:46-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:46 ross-5060a go-librespot[9556]: time="2024-11-25T16:17:46-05:00" level=debug msg="completed challenge" Nov 25 16:17:47 ross-5060a go-librespot[9556]: time="2024-11-25T16:17:47-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:47 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:47 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:47 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:47 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:48 ross-5060a volumio[981]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 25 16:17:48 ross-5060a volumio[981]: info: Received Get System Info Nov 25 16:17:48 ross-5060a volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 25 16:17:48 ross-5060a volumio[981]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 25 16:17:48 ross-5060a volumio[981]: info: Discovery: Getting this device information Nov 25 16:17:48 ross-5060a volumio[981]: info: CoreCommandRouter::volumioGetState Nov 25 16:17:48 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:17:48 ross-5060a volumio[981]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 25 16:17:50 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:50 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6205. Nov 25 16:17:50 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:50 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:50 ross-5060a go-librespot[9569]: Librespot-go daemon starting... Nov 25 16:17:50 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:50-05:00" level=info msg="generated new device id: d36c803e61d6155bc0d6bcb721fee39573e58166" Nov 25 16:17:50 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:50-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:50 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:50 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:50-05:00" level=debug msg="new websocket client" Nov 25 16:17:50 ross-5060a volumio[981]: info: Connection to go-librespot Websocket established Nov 25 16:17:50 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:50-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:17:50 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:50-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:17:50 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:50-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:17:50 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:50-05:00" level=debug msg="zeroconf server listening on port 46299" Nov 25 16:17:50 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:50-05:00" level=debug msg="obtained new client token: AADi6ULDNfJprelZM915o3gkf3+UINUIdmoyRyb4C/EmR8WC+pi8tISllWJvnS9pvKjncStFyFhr5lFOosUS31x827GPCj6oC/YQT7AyOxCTOVWUVCPvEBm23emsnxyJkZBujA8rXatcZqgQk+MmYuCQvUKTLAFmt8432ox4P6Bs3ppDowtn27oaL8D5mHTI0fOxiWgaJVEV3kEDJM9GSQUznVJV1LVHDpIdM2kCIOHXgW73M1sIbq9qb44=" Nov 25 16:17:50 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:50-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:51 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:51-05:00" level=debug msg="completed challenge" Nov 25 16:17:51 ross-5060a go-librespot[9569]: time="2024-11-25T16:17:51-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:51 ross-5060a volumio[981]: info: Connection to go-librespot Websocket closed Nov 25 16:17:51 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:51 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:53 ross-5060a volumio[981]: info: Getting Spotify volume Nov 25 16:17:53 ross-5060a volumio[981]: (node:981) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:53 ross-5060a volumio[981]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 25 16:17:53 ross-5060a volumio[981]: (node:981) 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: 2241) Nov 25 16:17:53 ross-5060a volumio[981]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 25 16:17:53 ross-5060a volumio[981]: info: CoreCommandRouter::volumioGetState Nov 25 16:17:53 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:17:53 ross-5060a volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Nov 25 16:17:54 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:54 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:54 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:54 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6206. Nov 25 16:17:54 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:54 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:54 ross-5060a go-librespot[9595]: Librespot-go daemon starting... Nov 25 16:17:54 ross-5060a go-librespot[9595]: time="2024-11-25T16:17:54-05:00" level=info msg="generated new device id: 4bf27503b9ebebdbf652942b19ab8b22be7ea225" Nov 25 16:17:54 ross-5060a go-librespot[9595]: time="2024-11-25T16:17:54-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:54 ross-5060a go-librespot[9595]: time="2024-11-25T16:17:54-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 16:17:54 ross-5060a go-librespot[9595]: time="2024-11-25T16:17:54-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 25 16:17:54 ross-5060a go-librespot[9595]: time="2024-11-25T16:17:54-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 25 16:17:54 ross-5060a go-librespot[9595]: time="2024-11-25T16:17:54-05:00" level=debug msg="zeroconf server listening on port 37903" Nov 25 16:17:55 ross-5060a go-librespot[9595]: time="2024-11-25T16:17:55-05:00" level=debug msg="obtained new client token: AAC9X2cw5ZURx93vBchoApJQje+pgvIqxI/BagIEZdDdKy87RJGv6XY0BLVOY5KfJhKNFsGasAohL0o7KVOpAck0wxQ/TnJc5PzHuFA5SII9rC5dS/LLc0SvmCXqBw8eZoI7iU5WU3IRgUIR2kA0tctescnnTlfRsPz7VZMHb59nXtsDdWRyEFtUg0LARcLBUqe1wA0n0y5MSffD4WDc7uq5lHYWwboVMUSQhZvWkZWgGEEXIn3gSZcc" Nov 25 16:17:55 ross-5060a go-librespot[9595]: time="2024-11-25T16:17:55-05:00" level=debug msg="completed keyexchange" Nov 25 16:17:55 ross-5060a go-librespot[9595]: time="2024-11-25T16:17:55-05:00" level=debug msg="completed challenge" Nov 25 16:17:55 ross-5060a go-librespot[9595]: time="2024-11-25T16:17:55-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:17:55 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:17:56 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:17:57 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:17:57 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:17:59 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:17:59 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6207. Nov 25 16:17:59 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:17:59 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:17:59 ross-5060a go-librespot[9612]: Librespot-go daemon starting... Nov 25 16:17:59 ross-5060a go-librespot[9612]: time="2024-11-25T16:17:59-05:00" level=info msg="generated new device id: 8d17010027855e30d4b5d27651c4f2006360b87c" Nov 25 16:17:59 ross-5060a go-librespot[9612]: time="2024-11-25T16:17:59-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:17:59 ross-5060a go-librespot[9612]: time="2024-11-25T16:17:59-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 16:17:59 ross-5060a go-librespot[9612]: time="2024-11-25T16:17:59-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 25 16:17:59 ross-5060a go-librespot[9612]: time="2024-11-25T16:17:59-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 25 16:17:59 ross-5060a go-librespot[9612]: time="2024-11-25T16:17:59-05:00" level=debug msg="zeroconf server listening on port 45935" Nov 25 16:17:59 ross-5060a go-librespot[9612]: time="2024-11-25T16:17:59-05:00" level=debug msg="obtained new client token: AACZdon7dePmEPe5PDBiIBDt7q4tTJgfsenFds5cw3JlG4QCI4Vg5Re76hLVajN4oYM1OOin2ivIjyyi0EAElEddAXcmqWs/iNN5Kttr8prgPFvD/hFMARo35WsA/BosZQFk+Zzdji+hY7ABdonQffY3ifHdOZGTnyfNxwiD6hfldqa2OqfDWv1qtM8xTJQMthQ/IXywyn935eoCJN7UxHMg2U/zbCF414MK7ZUBgvRKsNswhI8gl5AiBes=" Nov 25 16:17:59 ross-5060a go-librespot[9612]: time="2024-11-25T16:17:59-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:00 ross-5060a go-librespot[9612]: time="2024-11-25T16:18:00-05:00" level=debug msg="completed challenge" Nov 25 16:18:00 ross-5060a go-librespot[9612]: time="2024-11-25T16:18:00-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:00 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:00 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:00 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:00 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:03 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:03 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:03 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:03 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6208. Nov 25 16:18:03 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:03 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:03 ross-5060a go-librespot[9638]: Librespot-go daemon starting... Nov 25 16:18:03 ross-5060a go-librespot[9638]: time="2024-11-25T16:18:03-05:00" level=info msg="generated new device id: 241a1b2c60267250099b8ba3069a156d9335c17a" Nov 25 16:18:03 ross-5060a go-librespot[9638]: time="2024-11-25T16:18:03-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:04 ross-5060a go-librespot[9638]: time="2024-11-25T16:18:04-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:18:04 ross-5060a go-librespot[9638]: time="2024-11-25T16:18:04-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:18:04 ross-5060a go-librespot[9638]: time="2024-11-25T16:18:04-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:18:04 ross-5060a go-librespot[9638]: time="2024-11-25T16:18:04-05:00" level=debug msg="zeroconf server listening on port 36833" Nov 25 16:18:04 ross-5060a go-librespot[9638]: time="2024-11-25T16:18:04-05:00" level=debug msg="obtained new client token: AADlJr+c8J6N8eus1br3N1xVKN9nUJOTpdu/9X2Kj8IFCFbFDZHaEuYiaDRjly0q1jSBi+59v12PVgqUbOg62rN3nhWjmut6YCKaB1R00vVTD0vocS0YJHkxlZrb+aeERC4vrW4vKn2xsnnfIWEWAnuObxepGwH0JwbiuyNeK+1JzcyrQYUOJu2ztSsrwU4k0IgEGIMY37bi+A5rRyn5YeXem67gjsvtpPxZAXbd1uj88bF52LxKwacFtzI=" Nov 25 16:18:04 ross-5060a go-librespot[9638]: time="2024-11-25T16:18:04-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:05 ross-5060a go-librespot[9638]: time="2024-11-25T16:18:05-05:00" level=debug msg="completed challenge" Nov 25 16:18:05 ross-5060a go-librespot[9638]: time="2024-11-25T16:18:05-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:05 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:05 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:06 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:06 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:08 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:08 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6209. Nov 25 16:18:08 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:08 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:08 ross-5060a go-librespot[9655]: Librespot-go daemon starting... Nov 25 16:18:08 ross-5060a go-librespot[9655]: time="2024-11-25T16:18:08-05:00" level=info msg="generated new device id: b8f1928dce3a0faffe63a6de84a52dc3a71d5d0d" Nov 25 16:18:08 ross-5060a go-librespot[9655]: time="2024-11-25T16:18:08-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:08 ross-5060a go-librespot[9655]: time="2024-11-25T16:18:08-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:18:08 ross-5060a go-librespot[9655]: time="2024-11-25T16:18:08-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:18:08 ross-5060a go-librespot[9655]: time="2024-11-25T16:18:08-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:18:08 ross-5060a go-librespot[9655]: time="2024-11-25T16:18:08-05:00" level=debug msg="zeroconf server listening on port 33365" Nov 25 16:18:08 ross-5060a go-librespot[9655]: time="2024-11-25T16:18:08-05:00" level=debug msg="obtained new client token: AACaCT4EOOKZLl42OKYUsg+XE3WQA/KIBc5CDk6NZm2sPR67j/geVvLgxQQDHqI9JA9BRZQfHjK/sEVMdTV/V+/0B+LEEykFY1BuBcoUvbUIyiNgycyMcQ2tsJbNtj0rws27218MeFbbGIgwEDOYkfTSsZaHRuSVpLRz4QS0QN7kNKJ5u2mNM4knTi+j/4B4IEPatZ3xLRVXx2Jfnk5+TaFUeZjVazL0sBndVD3EhxziNIfDcaNT1Gi7HZU=" Nov 25 16:18:08 ross-5060a go-librespot[9655]: time="2024-11-25T16:18:08-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:09 ross-5060a go-librespot[9655]: time="2024-11-25T16:18:09-05:00" level=debug msg="completed challenge" Nov 25 16:18:09 ross-5060a go-librespot[9655]: time="2024-11-25T16:18:09-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:09 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:09 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:09 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:09 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:12 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:12 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:12 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:12 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6210. Nov 25 16:18:12 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:12 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:12 ross-5060a go-librespot[9682]: Librespot-go daemon starting... Nov 25 16:18:12 ross-5060a go-librespot[9682]: time="2024-11-25T16:18:12-05:00" level=info msg="generated new device id: e0b9ef88adb0529af2ff71109425cfdd58976827" Nov 25 16:18:12 ross-5060a go-librespot[9682]: time="2024-11-25T16:18:12-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:12 ross-5060a go-librespot[9682]: time="2024-11-25T16:18:12-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:18:12 ross-5060a go-librespot[9682]: time="2024-11-25T16:18:12-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:18:12 ross-5060a go-librespot[9682]: time="2024-11-25T16:18:12-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:18:13 ross-5060a go-librespot[9682]: time="2024-11-25T16:18:13-05:00" level=debug msg="zeroconf server listening on port 45843" Nov 25 16:18:13 ross-5060a go-librespot[9682]: time="2024-11-25T16:18:13-05:00" level=debug msg="obtained new client token: AABkeniUVr/eYzJPKWtzcX6WDWJrD+lu8zrfJRwnfb8Me2hZRfmhzhuU0BZ1Jw/jt3X8cu4GfbgFVT3A8lK3Xd4Hj58B4znhA7Rmp52ZiDbIxj5ft4qaqRP+Xiu1LWPJ/0TvMgNmGy9jnSDoDxQoyWWv/ywQrZM6+iwaKIwdRmOyDiLX6ywqruKJ5wMPbwGodY7mM+wpg2UihvDHDntyIqseJ7gEv6RFbkKtvukhVNxo0XbnI1PsuQKPnOY=" Nov 25 16:18:14 ross-5060a go-librespot[9682]: time="2024-11-25T16:18:14-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:14 ross-5060a go-librespot[9682]: time="2024-11-25T16:18:14-05:00" level=debug msg="completed challenge" Nov 25 16:18:14 ross-5060a go-librespot[9682]: time="2024-11-25T16:18:14-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:14 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:14 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:15 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:15 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:17 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:17 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6211. Nov 25 16:18:17 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:17 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:17 ross-5060a go-librespot[9698]: Librespot-go daemon starting... Nov 25 16:18:17 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:17-05:00" level=info msg="generated new device id: 85cdd2b85b8cab51d659f40776c19e9a40ec5ec8" Nov 25 16:18:17 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:17-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:18 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:18-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:18:18 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:18-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:18:18 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:18-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:18:18 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:18-05:00" level=debug msg="zeroconf server listening on port 45585" Nov 25 16:18:18 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:18-05:00" level=debug msg="obtained new client token: AACnDENx2gMUJ4P0GrPSXqNHQhqyLyQ9IvUGHFseMUZXSQ6aLPTwrvOqWwDFplJBRbXpLYbuPRF1BkmuRTecDiD50UYOoEvLlsykA27YPiJ0vi3+wU419LXlntE4aTbhh6Ff7MCMkEhfAG3VF2AHN5khB7oGAQdT3FCQ/4RmSjICPebydaBJDa/TirWdGS/I1cxzZoSCGEZ3c59dFws5/CUQVBNXdW4WNq6aonyggoktsT3ThIEEMQmCy8Y=" Nov 25 16:18:18 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:18 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:18-05:00" level=debug msg="new websocket client" Nov 25 16:18:18 ross-5060a volumio[981]: info: Connection to go-librespot Websocket established Nov 25 16:18:18 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:18-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:19 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:19-05:00" level=debug msg="completed challenge" Nov 25 16:18:19 ross-5060a go-librespot[9698]: time="2024-11-25T16:18:19-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:19 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:19 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:19 ross-5060a volumio[981]: info: Connection to go-librespot Websocket closed Nov 25 16:18:21 ross-5060a volumio[981]: info: Getting Spotify volume Nov 25 16:18:21 ross-5060a volumio[981]: (node:981) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:21 ross-5060a volumio[981]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 25 16:18:21 ross-5060a volumio[981]: (node:981) 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: 2242) Nov 25 16:18:21 ross-5060a volumio[981]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 25 16:18:21 ross-5060a volumio[981]: info: CoreCommandRouter::volumioGetState Nov 25 16:18:21 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:18:21 ross-5060a volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Nov 25 16:18:22 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:22 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:22 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:22 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6212. Nov 25 16:18:22 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:22 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:22 ross-5060a go-librespot[9725]: Librespot-go daemon starting... Nov 25 16:18:22 ross-5060a go-librespot[9725]: time="2024-11-25T16:18:22-05:00" level=info msg="generated new device id: 7774a298a16c07d2e15dee35ee3d76ad54c63ebb" Nov 25 16:18:22 ross-5060a go-librespot[9725]: time="2024-11-25T16:18:22-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:22 ross-5060a go-librespot[9725]: time="2024-11-25T16:18:22-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 16:18:22 ross-5060a go-librespot[9725]: time="2024-11-25T16:18:22-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 25 16:18:22 ross-5060a go-librespot[9725]: time="2024-11-25T16:18:22-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 25 16:18:22 ross-5060a go-librespot[9725]: time="2024-11-25T16:18:22-05:00" level=debug msg="zeroconf server listening on port 36653" Nov 25 16:18:23 ross-5060a go-librespot[9725]: time="2024-11-25T16:18:23-05:00" level=debug msg="obtained new client token: AABVP/QKrdjMxmUCW/6A1di7WBDkpjQtcD5fzuI5kFcSREKbrkkcF6woYh6hVROmhueDit5EhFscNbCVK9wdqBWRm8p/VkMBbj7k7stMEBtr8DK3OMyJuu/9dVeEO2ny+qd0iceLTXnOpL4PMeRGa8hmSXzDHy/kmkJ9BeiUhL9wdGB9Wk3e03DpNidzvlUffVaQBxftigMr7Hr97xrQch6RzpH6HW3AEegGbm2/O5E3mtg9SmJQCqmVDgU=" Nov 25 16:18:23 ross-5060a go-librespot[9725]: time="2024-11-25T16:18:23-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:23 ross-5060a go-librespot[9725]: time="2024-11-25T16:18:23-05:00" level=debug msg="completed challenge" Nov 25 16:18:23 ross-5060a go-librespot[9725]: time="2024-11-25T16:18:23-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:23 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:23 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:25 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:25 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:26 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:26 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6213. Nov 25 16:18:26 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:26 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:26 ross-5060a go-librespot[9742]: Librespot-go daemon starting... Nov 25 16:18:26 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:26-05:00" level=info msg="generated new device id: 857786f7e05f4fddde923e88c0365e873c39996b" Nov 25 16:18:26 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:26-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:27 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:27-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:18:27 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:27-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:18:27 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:27-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:18:27 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:27-05:00" level=debug msg="zeroconf server listening on port 44567" Nov 25 16:18:27 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:27-05:00" level=debug msg="obtained new client token: AACWnjpuX26jsOApUyPCnBZJcE4R+J7DFUJGCNHFlHsQ/l2YAww0oAGLvI62UB5s432sn6ngV2vy/2f/J1GxSV+ofFX+tgpMYZQgi48ASIq9FZOA1qq1Kl3gMyk7r0nvQwRGafomjXsCi7VUNcL9fO4JS0c9pl+zmUqjyykH7tEO+K0iSR8V+dvzp9kMsYXTg02Sm4qoaS3ci5vScSPMEF0BVxtfUsip7ZxtwNfgxtaMQF69XoDJZQWtiX0=" Nov 25 16:18:27 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:27-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:28 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:28 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:28-05:00" level=debug msg="new websocket client" Nov 25 16:18:28 ross-5060a volumio[981]: info: Connection to go-librespot Websocket established Nov 25 16:18:28 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:28-05:00" level=debug msg="completed challenge" Nov 25 16:18:28 ross-5060a go-librespot[9742]: time="2024-11-25T16:18:28-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:28 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:28 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:28 ross-5060a volumio[981]: info: Connection to go-librespot Websocket closed Nov 25 16:18:30 ross-5060a volumiologrotate[445]: ls: cannot access '/var/log/samba/log.wb-ROSS': No such file or directory Nov 25 16:18:30 ross-5060a volumiologrotate[445]: ls: cannot access '5060A': No such file or directory Nov 25 16:18:31 ross-5060a volumio[981]: info: Getting Spotify volume Nov 25 16:18:31 ross-5060a volumio[981]: (node:981) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:31 ross-5060a volumio[981]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 25 16:18:31 ross-5060a volumio[981]: (node:981) 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: 2243) Nov 25 16:18:31 ross-5060a volumio[981]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 25 16:18:31 ross-5060a volumio[981]: info: CoreCommandRouter::volumioGetState Nov 25 16:18:31 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:18:31 ross-5060a volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Nov 25 16:18:31 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:31 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:31 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:31 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6214. Nov 25 16:18:31 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:31 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:31 ross-5060a go-librespot[9810]: Librespot-go daemon starting... Nov 25 16:18:31 ross-5060a go-librespot[9810]: time="2024-11-25T16:18:31-05:00" level=info msg="generated new device id: a2cc8ed8dd10c9710aa41de71bf6f9b39b4145b9" Nov 25 16:18:31 ross-5060a go-librespot[9810]: time="2024-11-25T16:18:31-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:31 ross-5060a go-librespot[9810]: time="2024-11-25T16:18:31-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:18:31 ross-5060a go-librespot[9810]: time="2024-11-25T16:18:31-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:18:31 ross-5060a go-librespot[9810]: time="2024-11-25T16:18:31-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:18:31 ross-5060a go-librespot[9810]: time="2024-11-25T16:18:31-05:00" level=debug msg="zeroconf server listening on port 41775" Nov 25 16:18:32 ross-5060a go-librespot[9810]: time="2024-11-25T16:18:32-05:00" level=debug msg="obtained new client token: AAA2QLWheeSGc4+6yN2E8moI0dLYxGnNRf57SFBRrl2DoMLv/zCWLmHytBMvDFIsAh+BGI6TlZd29QHeV3mW0klawE1GINhbBpOciXWjSWSrkiRC1c3dq7E8S2YwxYFxB92yta6U1j4WecEFYu123QO98AYvYHbO5BDS9MUZaTayGHDlhR19QP6yUmzlPsNBOOyyGZQmTy15tkFfNWFOsptxYdl0xrqLGwAbo9Kg0ZcV0/2asEDaGnbW" Nov 25 16:18:32 ross-5060a go-librespot[9810]: time="2024-11-25T16:18:32-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:32 ross-5060a go-librespot[9810]: time="2024-11-25T16:18:32-05:00" level=debug msg="completed challenge" Nov 25 16:18:32 ross-5060a go-librespot[9810]: time="2024-11-25T16:18:32-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:32 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:32 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:34 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:34 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:36 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:36 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6215. Nov 25 16:18:36 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:36 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:36 ross-5060a go-librespot[9825]: Librespot-go daemon starting... Nov 25 16:18:36 ross-5060a volumio[981]: info: Clearing queue after UPNP request Nov 25 16:18:36 ross-5060a go-librespot[9825]: time="2024-11-25T16:18:36-05:00" level=info msg="generated new device id: 6352c61b73d02ef1231892f680c1d5a8c4ba9566" Nov 25 16:18:36 ross-5060a go-librespot[9825]: time="2024-11-25T16:18:36-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:36 ross-5060a go-librespot[9825]: time="2024-11-25T16:18:36-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:18:36 ross-5060a go-librespot[9825]: time="2024-11-25T16:18:36-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:18:36 ross-5060a go-librespot[9825]: time="2024-11-25T16:18:36-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:18:36 ross-5060a volumio[981]: info: CoreStateMachine::ClearQueue Nov 25 16:18:36 ross-5060a volumio[981]: info: CoreStateMachine::stop Nov 25 16:18:36 ross-5060a volumio[981]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 25 16:18:36 ross-5060a volumio[981]: info: CorePlayQueue::clearPlayQueue Nov 25 16:18:36 ross-5060a volumio[981]: info: CorePlayQueue::saveQueue Nov 25 16:18:36 ross-5060a volumio[981]: info: CoreCommandRouter::volumioPushState Nov 25 16:18:36 ross-5060a volumio[981]: info: CoreCommandRouter::volumioPushQueue Nov 25 16:18:36 ross-5060a go-librespot[9825]: time="2024-11-25T16:18:36-05:00" level=debug msg="zeroconf server listening on port 46551" Nov 25 16:18:36 ross-5060a volumio[981]: error: Upnp client error: Error: This socket has been ended by the other party Nov 25 16:18:36 ross-5060a volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Nov 25 16:18:36 ross-5060a go-librespot[9825]: time="2024-11-25T16:18:36-05:00" level=debug msg="obtained new client token: AADJ43F30Bjy/hef54rCx8hZ+6u7kVjR/qKYFIaT/bc9GNhTtA1Fxmknn56d83LDAC+1qoRwYCkU6/fZiyL1/I201KKBJjRbTwbkGq7kalC8VmGiPjIYSnWB2MzpDn9Ygk4Dcjw9WSDYyyEz480XcwhjpGd7TOO4/a2jKVeSQ0iJ5JVZExYAJZXulqpryX4WddzcyZWiDXJr5d6JZdcUfuM6Jy2LJIao04Zo/TDkqC16lEkY4lTBYnFCziI=" Nov 25 16:18:36 ross-5060a go-librespot[9825]: time="2024-11-25T16:18:36-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:37 ross-5060a go-librespot[9825]: time="2024-11-25T16:18:37-05:00" level=debug msg="completed challenge" Nov 25 16:18:37 ross-5060a go-librespot[9825]: time="2024-11-25T16:18:37-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:37 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:37 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:37 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:37 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:38 ross-5060a volumio[981]: info: Starting UPNP Playback Nov 25 16:18:38 ross-5060a volumio[981]: info: Preparing playback through UPNP Nov 25 16:18:38 ross-5060a volumio[981]: info: CoreCommandRouter::volumioGetState Nov 25 16:18:38 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:18:38 ross-5060a volumio[981]: info: CoreStateMachine::setConsumeUpdateService mpd Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 7ms Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 4ms Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 3ms Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 3ms Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 3ms Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 2ms Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 1ms Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 2ms Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 3ms Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 4ms Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 3ms Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 2ms Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 4ms Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 3ms Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 2ms Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: Nov 25 16:18:38 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:38 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 3ms Nov 25 16:18:38 ross-5060a volumio[981]: info: ------------------------------ 2ms Nov 25 16:18:39 ross-5060a volumio[1320]: 50 Nov 25 16:18:39 ross-5060a volumio[1320]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 25 16:18:39 ross-5060a volumio[1320]: Dload Upload Total Spent Left Speed Nov 25 16:18:39 ross-5060a volumio[981]: info: Nov 25 16:18:39 ross-5060a volumio[981]: ---------------------------- Client requests Volume 50 Nov 25 16:18:39 ross-5060a volumio[981]: info: VolumeController::SetAlsaVolume50 Nov 25 16:18:39 ross-5060a volumio[981]: info: CoreStateMachine::pushState Nov 25 16:18:39 ross-5060a volumio[981]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 25 16:18:39 ross-5060a volumio[981]: info: CoreCommandRouter::volumioPushState Nov 25 16:18:39 ross-5060a volumio[1320]: [158B blob data] Nov 25 16:18:39 ross-5060a volumio[1320]: {"time":1732569519184,"response":"volume Success"}50 Nov 25 16:18:39 ross-5060a volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Nov 25 16:18:39 ross-5060a volumio[981]: SPOTIFY: SPOTIFY VOLUME 10 Nov 25 16:18:39 ross-5060a volumio[981]: SPOTIFY: VOLUMIO VOLUME 50 Nov 25 16:18:39 ross-5060a volumio[981]: SPOTIFY: DELTA VOLUME ENOUGH: true Nov 25 16:18:39 ross-5060a volumio[981]: info: Setting Spotify Volume from Volumio: 50 Nov 25 16:18:40 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:40 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6216. Nov 25 16:18:40 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:40 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:40 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:40 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:40 ross-5060a go-librespot[9862]: Librespot-go daemon starting... Nov 25 16:18:40 ross-5060a go-librespot[9862]: time="2024-11-25T16:18:40-05:00" level=info msg="generated new device id: 148e3c005b668effceb1c0974f998fe7ecc480ea" Nov 25 16:18:40 ross-5060a go-librespot[9862]: time="2024-11-25T16:18:40-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:40 ross-5060a volumio[981]: SPOTIFY: SETTING SPOTIFY VOLUME 50 Nov 25 16:18:40 ross-5060a volumio[981]: info: Sending Spotify command with payload to local API: /player/volume Nov 25 16:18:40 ross-5060a go-librespot[9862]: time="2024-11-25T16:18:40-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 16:18:40 ross-5060a go-librespot[9862]: time="2024-11-25T16:18:40-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 25 16:18:40 ross-5060a go-librespot[9862]: time="2024-11-25T16:18:40-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 25 16:18:40 ross-5060a go-librespot[9862]: time="2024-11-25T16:18:40-05:00" level=debug msg="zeroconf server listening on port 33493" Nov 25 16:18:41 ross-5060a go-librespot[9862]: time="2024-11-25T16:18:41-05:00" level=debug msg="obtained new client token: AABaKzElWxLkMI3ajE9XGax/gy3gfPdvL0RIxEFyRWhHojb5Oubkt412D3MQ2Ymqsa6OAYAM55LG0tzmjWaZnMuoy+Ai8P2Ddsxx4XhbUL0wFZZQw81Ejv/d3Wn8c1SlR2ayO6D34QfsXLGjOurSWZvvOHMPtnrkHmpbOBCW9SHIVlc15acOv7cUWk9LcSEd/weai5sr+XucGQU/xWhGCzk/BPNG9Wb0R1L/6ea5y+gTdcawEol+9Iee" Nov 25 16:18:41 ross-5060a kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Nov 25 16:18:41 ross-5060a volumio[981]: info: Nov 25 16:18:41 ross-5060a volumio[981]: ---------------------------- MPD announces state update: player Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::getState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand status Nov 25 16:18:41 ross-5060a volumio[981]: info: Nov 25 16:18:41 ross-5060a volumio[981]: ---------------------------- MPD announces state update: player Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::getState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand status Nov 25 16:18:41 ross-5060a volumio[981]: info: Nov 25 16:18:41 ross-5060a volumio[981]: ---------------------------- MPD announces state update: player Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::getState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand status Nov 25 16:18:41 ross-5060a volumio[981]: info: Nov 25 16:18:41 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:41 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:41 ross-5060a volumio[981]: info: Nov 25 16:18:41 ross-5060a volumio[981]: ---------------------------- MPD announces state update: player Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand status took 18 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand status took 18 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::getState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand status Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 25 16:18:41 ross-5060a volumio[981]: info: Nov 25 16:18:41 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:41 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:41 ross-5060a volumio[981]: info: Nov 25 16:18:41 ross-5060a volumio[981]: ---------------------------- MPD announces state update: player Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::getState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand status Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand status took 22 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: info: ------------------------------ 8ms Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand status took 8 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand playlistinfo took 6 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand playlistinfo took 6 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: info: ------------------------------ 4ms Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand status took 3 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseTrackInfo Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseTrackInfo Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::servicePushState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: In UPNP mode Nov 25 16:18:41 ross-5060a volumio[981]: verbose: STATE SERVICE {"status":"play","position":1,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"223 Kbps","isStreaming":false,"title":"fip-hifi.aac","artist":"fip-hifi.aac","album":null,"uri":"http://icecast.radiofrance.fr/fip-hifi.aac","trackType":"aac"} Nov 25 16:18:41 ross-5060a volumio[981]: verbose: CURRENT POSITION 0 Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState stateService play Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState currentStatus stop Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::servicePushState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: In UPNP mode Nov 25 16:18:41 ross-5060a volumio[981]: verbose: STATE SERVICE {"status":"play","position":1,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"223 Kbps","isStreaming":false,"title":"fip-hifi.aac","artist":"fip-hifi.aac","album":null,"uri":"http://icecast.radiofrance.fr/fip-hifi.aac","trackType":"aac"} Nov 25 16:18:41 ross-5060a volumio[981]: verbose: CURRENT POSITION 0 Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState stateService play Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState currentStatus play Nov 25 16:18:41 ross-5060a volumio[981]: info: Received an update from plugin. extracting info from payload Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:18:41 ross-5060a volumio[981]: info: ------------------------------ 34ms Nov 25 16:18:41 ross-5060a volumio[981]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 25 16:18:41 ross-5060a volumio[981]: info: ------------------------------ 34ms Nov 25 16:18:41 ross-5060a volumio[981]: info: Nov 25 16:18:41 ross-5060a volumio[981]: ---------------------------- MPD announces system playlist update Nov 25 16:18:41 ross-5060a volumio[981]: info: Ignoring MPD Status Update Nov 25 16:18:41 ross-5060a volumio[981]: info: Nov 25 16:18:41 ross-5060a volumio[981]: ---------------------------- MPD announces state update: player Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::getState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand status Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand playlistinfo took 10 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand playlistinfo took 9 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand playlistinfo took 10 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseTrackInfo Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseTrackInfo Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::servicePushState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: In UPNP mode Nov 25 16:18:41 ross-5060a volumio[981]: verbose: STATE SERVICE {"status":"play","position":1,"seek":31,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"223 Kbps","isStreaming":false,"title":"fip-hifi.aac","artist":"fip-hifi.aac","album":null,"uri":"http://icecast.radiofrance.fr/fip-hifi.aac","trackType":"aac"} Nov 25 16:18:41 ross-5060a volumio[981]: verbose: CURRENT POSITION 0 Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState stateService play Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState currentStatus play Nov 25 16:18:41 ross-5060a volumio[981]: info: Received an update from plugin. extracting info from payload Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::servicePushState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: In UPNP mode Nov 25 16:18:41 ross-5060a volumio[981]: verbose: STATE SERVICE {"status":"play","position":1,"seek":987,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"223 Kbps","isStreaming":false,"title":"fip-hifi.aac","artist":"fip-hifi.aac","album":null,"uri":"http://icecast.radiofrance.fr/fip-hifi.aac","trackType":"aac"} Nov 25 16:18:41 ross-5060a volumio[981]: verbose: CURRENT POSITION 0 Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState stateService play Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState currentStatus play Nov 25 16:18:41 ross-5060a volumio[981]: info: Received an update from plugin. extracting info from payload Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::servicePushState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: In UPNP mode Nov 25 16:18:41 ross-5060a volumio[981]: verbose: STATE SERVICE {"status":"play","position":1,"seek":987,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"223 Kbps","isStreaming":false,"title":"fip-hifi.aac","artist":"fip-hifi.aac","album":null,"uri":"http://icecast.radiofrance.fr/fip-hifi.aac","trackType":"aac"} Nov 25 16:18:41 ross-5060a volumio[981]: verbose: CURRENT POSITION 0 Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState stateService play Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState currentStatus play Nov 25 16:18:41 ross-5060a volumio[981]: info: Received an update from plugin. extracting info from payload Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:18:41 ross-5060a volumio[981]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 25 16:18:41 ross-5060a volumio[981]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 25 16:18:41 ross-5060a volumio[981]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 25 16:18:41 ross-5060a volumio[981]: info: ------------------------------ 44ms Nov 25 16:18:41 ross-5060a volumio[981]: info: ------------------------------ 29ms Nov 25 16:18:41 ross-5060a volumio[981]: info: ------------------------------ 23ms Nov 25 16:18:41 ross-5060a volumio[981]: info: ------------------------------ 12ms Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand status took 12 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 25 16:18:41 ross-5060a volumio[981]: info: sendMpdCommand playlistinfo took 1 milliseconds Nov 25 16:18:41 ross-5060a volumio[981]: verbose: ControllerMpd::parseTrackInfo Nov 25 16:18:41 ross-5060a volumio[981]: info: ControllerMpd::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::servicePushState Nov 25 16:18:41 ross-5060a volumio[981]: verbose: In UPNP mode Nov 25 16:18:41 ross-5060a volumio[981]: verbose: STATE SERVICE {"status":"play","position":1,"seek":987,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"223 Kbps","isStreaming":false,"title":"fip-hifi.aac","artist":"fip-hifi.aac","album":null,"uri":"http://icecast.radiofrance.fr/fip-hifi.aac","trackType":"aac"} Nov 25 16:18:41 ross-5060a volumio[981]: verbose: CURRENT POSITION 0 Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState stateService play Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::syncState currentStatus play Nov 25 16:18:41 ross-5060a volumio[981]: info: Received an update from plugin. extracting info from payload Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Nov 25 16:18:41 ross-5060a volumio[981]: info: CoreStateMachine::pushState Nov 25 16:18:41 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:18:41 ross-5060a volumio[981]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 25 16:18:41 ross-5060a volumio[981]: info: ------------------------------ 17ms Nov 25 16:18:41 ross-5060a go-librespot[9862]: time="2024-11-25T16:18:41-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:41 ross-5060a go-librespot[9862]: time="2024-11-25T16:18:41-05:00" level=debug msg="completed challenge" Nov 25 16:18:41 ross-5060a go-librespot[9862]: time="2024-11-25T16:18:41-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:41 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:41 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:41 ross-5060a volumio[981]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Nov 25 16:18:43 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:43 ross-5060a volumio[981]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:45 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:45 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6217. Nov 25 16:18:45 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:45 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:45 ross-5060a go-librespot[9903]: Librespot-go daemon starting... Nov 25 16:18:45 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:45-05:00" level=info msg="generated new device id: 307bd1ed32b4741b16dc3cc5dc05ed7fabd9103a" Nov 25 16:18:45 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:45-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:45 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:45-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Nov 25 16:18:45 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:45-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 25 16:18:45 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:45-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 25 16:18:45 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:45-05:00" level=debug msg="zeroconf server listening on port 38771" Nov 25 16:18:45 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:45-05:00" level=debug msg="obtained new client token: AAAySMaJc3F2ACvEYRQRV2KIC/DjZbeccVKGpOma0WWfFhlvn4l0aBQ4HJhfoRiXs4wMHgiu6ghlucKiIvRGvpJllirJxzkB7guvyDN/BtnMdqX0F5s4B0vOA3+R17BewaRQNwKuFfos64FQx0huKkwTLCLKFCwYbeLFBhA3MaEc47zriwWmQQv3/Oz21tsE0tq9h+3MqGROhIGlXG3JW06v1JFD9JM2oO/EOwyfjtqgNlf/iN0FJcYkwto=" Nov 25 16:18:46 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:46-05:00" level=debug msg="completed keyexchange" Nov 25 16:18:46 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:46-05:00" level=debug msg="completed challenge" Nov 25 16:18:46 ross-5060a volumio[981]: info: Initializing connection to go-librespot Websocket Nov 25 16:18:46 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:46-05:00" level=debug msg="new websocket client" Nov 25 16:18:46 ross-5060a volumio[981]: info: Connection to go-librespot Websocket established Nov 25 16:18:46 ross-5060a go-librespot[9903]: time="2024-11-25T16:18:46-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:18:46 ross-5060a volumio[981]: info: Connection to go-librespot Websocket closed Nov 25 16:18:46 ross-5060a systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:18:46 ross-5060a systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:18:49 ross-5060a volumio[981]: info: Getting Spotify volume Nov 25 16:18:49 ross-5060a volumio[981]: (node:981) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:18:49 ross-5060a volumio[981]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 25 16:18:49 ross-5060a volumio[981]: (node:981) 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: 2244) Nov 25 16:18:49 ross-5060a volumio[981]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 25 16:18:49 ross-5060a volumio[981]: info: CoreCommandRouter::volumioGetState Nov 25 16:18:49 ross-5060a volumio[981]: info: CorePlayQueue::getTrack 0 Nov 25 16:18:49 ross-5060a volumio[981]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 25 16:18:49 ross-5060a volumio[981]: TypeError: Cannot read property 'name' of undefined Nov 25 16:18:49 ross-5060a volumio[981]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Nov 25 16:18:49 ross-5060a volumio[981]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Nov 25 16:18:49 ross-5060a volumio[981]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:58:38) Nov 25 16:18:49 ross-5060a volumio[981]: at Socket.emit (events.js:315:20) Nov 25 16:18:49 ross-5060a volumio[981]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Nov 25 16:18:49 ross-5060a volumio[981]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Nov 25 16:18:49 ross-5060a volumio[981]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 25 16:18:49 ross-5060a systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:18:49 ross-5060a systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6218. Nov 25 16:18:49 ross-5060a systemd[1]: Stopped go-librespot Daemon. Nov 25 16:18:49 ross-5060a systemd[1]: Started go-librespot Daemon. Nov 25 16:18:49 ross-5060a go-librespot[9935]: Librespot-go daemon starting... Nov 25 16:18:49 ross-5060a go-librespot[9935]: time="2024-11-25T16:18:49-05:00" level=info msg="generated new device id: b8634057ce2fd97a0a8158b130b921aa0998eeef" Nov 25 16:18:49 ross-5060a go-librespot[9935]: time="2024-11-25T16:18:49-05:00" level=debug msg="stored credentials found for wakjin" Nov 25 16:18:50 ross-5060a sudo[9946]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-25 16:17 Nov 25 16:18:50 ross-5060a sudo[9946]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 25 16:18:50 ross-5060a go-librespot[9935]: time="2024-11-25T16:18:50-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 16:18:50 ross-5060a go-librespot[9935]: time="2024-11-25T16:18:50-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 25 16:18:50 ross-5060a go-librespot[9935]: time="2024-11-25T16:18:50-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 25 16:18:50 ross-5060a go-librespot[9935]: time="2024-11-25T16:18:50-05:00" level=debug msg="zeroconf server listening on port 36871" PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"