-- Logs begin at Thu 2019-02-14 21:11:59 AEDT, end at Mon 2025-03-10 09:04:37 AEDT. -- Mar 10 09:03:00 volumio ntpd[777]: Soliciting pool server 172.105.168.117 Mar 10 09:03:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 71. Mar 10 09:03:00 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:01 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:01 volumio go-librespot[2329]: go-librespot daemon starting... Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=debug msg="app state loaded" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=info msg="zeroconf server listening on port 33989" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=debug msg="obtained new client token: AACdHPF63cHvJ+SXE3o6mEa0eEwJ4v6YgFfwXlG5slkf27SIVeOPTLuZppJIxpNljSsFGfuJGqwWDhCPOA6ep/QXDzLWqCMf2/HVop/30CbCT+NuD7Xt5wdVwPH4Z89CWUbQEn5ZPQn+azGSIzYIjbueKxXphxWNMRYCestG/XwKaZFBS38ZajynayDOVyRqmkLUJO/MM68OPitwUNt4Jh9Zg3v9TCKfUhVh3+I0y/sd+MUIvoix5RW2sjYX" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:01 volumio go-librespot[2329]: time="2025-03-10T09:03:01+11:00" level=debug msg="completed challenge" Mar 10 09:03:01 volumio ntpd[777]: Soliciting pool server 129.250.35.250 Mar 10 09:03:02 volumio go-librespot[2329]: time="2025-03-10T09:03:02+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:02 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:02 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:02 volumio ntpd[777]: Soliciting pool server 180.150.8.191 Mar 10 09:03:03 volumio ntpd[777]: Soliciting pool server 203.132.94.154 Mar 10 09:03:03 volumio ntpd[777]: Soliciting pool server 67.219.100.202 Mar 10 09:03:04 volumio ntpd[777]: Soliciting pool server 119.18.6.37 Mar 10 09:03:05 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 72. Mar 10 09:03:05 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:05 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:05 volumio go-librespot[2337]: go-librespot daemon starting... Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=debug msg="app state loaded" Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:05 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=debug msg="new websocket client" Mar 10 09:03:05 volumio volumio[1065]: info: Connection to go-librespot Websocket established Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=info msg="zeroconf server listening on port 41877" Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=debug msg="obtained new client token: AAD1bRb/gfHR2rD0NNbuTZE58reWZErlAQ/TEPXLEgjDoZQScL5t77BMPpjQHrdspZTicYB1ledpU9/XEOnocepjF8/+/NIIg80rJR7rrV/t6querosXF+zmUZiwghCJR2gpFT2kpV4Q3FhSKTHxM3xX1twQdyqXxSFHf4Bon0LBg/A2RUj7QaS0IkGAPeiKhzgzy6g5BPPS2dkWK9tUhXQse6Z1Hxwb5YmPOb1u0bDwndoaU6UIRdzKFZf1" Mar 10 09:03:05 volumio go-librespot[2337]: time="2025-03-10T09:03:05+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:06 volumio ntpd[777]: Soliciting pool server 139.99.135.247 Mar 10 09:03:06 volumio go-librespot[2337]: time="2025-03-10T09:03:06+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:06 volumio go-librespot[2337]: time="2025-03-10T09:03:06+11:00" level=debug msg="completed challenge" Mar 10 09:03:06 volumio go-librespot[2337]: time="2025-03-10T09:03:06+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:06 volumio volumio[1065]: info: Connection to go-librespot Websocket closed Mar 10 09:03:06 volumio volumio[1065]: verbose: New Socket.io Connection to 192.168.86.29 from 192.168.86.248 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/AP4A.250205.002.B2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.137 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 15 Mar 10 09:03:06 volumio volumio[1065]: verbose: New Socket.io Connection to 192.168.86.29 from 192.168.86.248 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/AP4A.250205.002.B2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.137 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 16 Mar 10 09:03:06 volumio volumio[1065]: verbose: New Socket.io Connection to 192.168.86.29 from 192.168.86.248 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/AP4A.250205.002.B2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.137 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 17 Mar 10 09:03:06 volumio volumio[1065]: verbose: New Socket.io Connection to 192.168.86.29 from 192.168.86.248 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/AP4A.250205.002.B2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.137 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 18 Mar 10 09:03:06 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState Mar 10 09:03:06 volumio volumio[1065]: info: CorePlayQueue::getTrack 1 Mar 10 09:03:06 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 10 09:03:06 volumio volumio[1065]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Mar 10 09:03:06 volumio volumio[1065]: info: Listing playlists Mar 10 09:03:06 volumio volumio[1065]: info: CoreCommandRouter::volumioGetVisibleSources Mar 10 09:03:06 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 10 09:03:06 volumio volumio[1065]: info: CoreCommandRouter::volumioGetQueue Mar 10 09:03:06 volumio volumio[1065]: info: CoreStateMachine::getQueue Mar 10 09:03:06 volumio volumio[1065]: info: CorePlayQueue::getQueue Mar 10 09:03:06 volumio ntpd[777]: Soliciting pool server 162.159.200.1 Mar 10 09:03:08 volumio volumio[1065]: info: Getting Spotify volume Mar 10 09:03:08 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:08 volumio volumio[1065]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Mar 10 09:03:08 volumio volumio[1065]: (node:1065) 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: 24) Mar 10 09:03:08 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 19 Mar 10 09:03:08 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState Mar 10 09:03:08 volumio volumio[1065]: info: CorePlayQueue::getTrack 1 Mar 10 09:03:08 volumio volumio[1065]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 10 09:03:08 volumio volumio[1065]: info: CorePlayQueue::getTrack 1 Mar 10 09:03:08 volumio volumio[1065]: info: CorePlayQueue::getTrack 2 Mar 10 09:03:08 volumio volumio[1065]: info: Prefetching next song Mar 10 09:03:08 volumio volumio[1065]: info: [1741557788842] ControllerSpotify::prefetch Mar 10 09:03:08 volumio volumio[1065]: info: Sending Spotify command with payload to local API: /player/add_to_queue Mar 10 09:03:08 volumio volumio[1065]: error: Failed to send command to Spotify local API: /player/add_to_queue: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:09 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:09 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:09 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 73. Mar 10 09:03:09 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:09 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:09 volumio go-librespot[2345]: go-librespot daemon starting... Mar 10 09:03:09 volumio go-librespot[2345]: time="2025-03-10T09:03:09+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:09 volumio go-librespot[2345]: time="2025-03-10T09:03:09+11:00" level=debug msg="app state loaded" Mar 10 09:03:09 volumio go-librespot[2345]: time="2025-03-10T09:03:09+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:09 volumio go-librespot[2345]: time="2025-03-10T09:03:09+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:09 volumio go-librespot[2345]: time="2025-03-10T09:03:09+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:09 volumio go-librespot[2345]: time="2025-03-10T09:03:09+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:09 volumio go-librespot[2345]: time="2025-03-10T09:03:09+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:09 volumio go-librespot[2345]: time="2025-03-10T09:03:09+11:00" level=info msg="zeroconf server listening on port 39267" Mar 10 09:03:10 volumio go-librespot[2345]: time="2025-03-10T09:03:10+11:00" level=debug msg="obtained new client token: AABXLTebJUfULwSAMYt0x1REaVL7TIbLlFasWqSx+o1iYDC0zQrHMnPUdLvu6mv9NJ/XQ8u0qv6tafrM4R5NkFfsqYZwPYqU9Z8Zobw/MqVmw/2ENr8vY2LuJrF9ZBLemWCAxOSSnHKi0fkC7PsZT2Zckewi376lglo2lwtEQwgKILDYxZqjZFnJkzVrGy4FQnD8e6wsQ1L0TTRjFuZnJFVi3zdl5DHc9dWnIf/9u237F4XZvX2oNslm7A==" Mar 10 09:03:10 volumio go-librespot[2345]: time="2025-03-10T09:03:10+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:10 volumio go-librespot[2345]: time="2025-03-10T09:03:10+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:10 volumio go-librespot[2345]: time="2025-03-10T09:03:10+11:00" level=debug msg="completed challenge" Mar 10 09:03:10 volumio go-librespot[2345]: time="2025-03-10T09:03:10+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:10 volumio volumio[1065]: info: Executing endpoint metavolumio Mar 10 09:03:10 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 10 09:03:10 volumio volumio[1065]: info: Executing endpoint metavolumio Mar 10 09:03:10 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 10 09:03:12 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:12 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:13 volumio volumio[1065]: info: CoreStateMachine::startPlaybackTimer Mar 10 09:03:13 volumio volumio[1065]: info: CorePlayQueue::getTrack 2 Mar 10 09:03:13 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 10 09:03:13 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 10 09:03:13 volumio volumio[1065]: info: Discovery: Getting this device information Mar 10 09:03:13 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState Mar 10 09:03:13 volumio volumio[1065]: info: CorePlayQueue::getTrack 2 Mar 10 09:03:13 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 10 09:03:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 74. Mar 10 09:03:13 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:13 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:13 volumio go-librespot[2354]: go-librespot daemon starting... Mar 10 09:03:13 volumio go-librespot[2354]: time="2025-03-10T09:03:13+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:13 volumio go-librespot[2354]: time="2025-03-10T09:03:13+11:00" level=debug msg="app state loaded" Mar 10 09:03:13 volumio go-librespot[2354]: time="2025-03-10T09:03:13+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:13 volumio go-librespot[2354]: time="2025-03-10T09:03:13+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:13 volumio volumio[1065]: info: CoreStateMachine::pushState Mar 10 09:03:13 volumio volumio[1065]: info: CorePlayQueue::getTrack 2 Mar 10 09:03:13 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 10 09:03:13 volumio volumio[1065]: info: CoreCommandRouter::volumioPushState Mar 10 09:03:13 volumio volumio[1065]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 10 09:03:14 volumio go-librespot[2354]: time="2025-03-10T09:03:14+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:14 volumio go-librespot[2354]: time="2025-03-10T09:03:14+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:14 volumio go-librespot[2354]: time="2025-03-10T09:03:14+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:14 volumio go-librespot[2354]: time="2025-03-10T09:03:14+11:00" level=info msg="zeroconf server listening on port 33155" Mar 10 09:03:14 volumio go-librespot[2354]: time="2025-03-10T09:03:14+11:00" level=debug msg="obtained new client token: AAD33M2HsClnUkK5iGgS4+spz5icmP1IBFlSFIqhEG32tXz725ZE+iMN1Nxmqx0f8fg+ukUwTbgQuptunWIOt56EHWvRgkE/PsJvX3exd1G7x26RKyRTuW/xoeVBAeVy3goTeMKshqba/uwLsC6aaQKvwROHGNyd+48HrZSG7Y07O4UzTXHE7Y27XNsU5G4W1KUyNsJD9fvTQ9QIb1EladoRm0lu1aANEGlvc+hb/7nyErf8J622lGPEt2Rj" Mar 10 09:03:14 volumio go-librespot[2354]: time="2025-03-10T09:03:14+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:14 volumio go-librespot[2354]: time="2025-03-10T09:03:14+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:14 volumio go-librespot[2354]: time="2025-03-10T09:03:14+11:00" level=debug msg="completed challenge" Mar 10 09:03:14 volumio go-librespot[2354]: time="2025-03-10T09:03:14+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:15 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:15 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 75. Mar 10 09:03:17 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:18 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:18 volumio go-librespot[2363]: go-librespot daemon starting... Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=debug msg="app state loaded" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:18 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:18 volumio volumio[1065]: info: Connection to go-librespot Websocket established Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=debug msg="new websocket client" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=info msg="zeroconf server listening on port 38799" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=debug msg="obtained new client token: AACeXWUzpFEZcPo4gX0/ECfGQJ7nTlccNh3I6EqzC1vY3JfW0L1QmDsJFNRNSymJKrTWGJlD2stjv69YVzLJRDLfvvW1ofkZspUOlhs63WV4BObQdOxFQFOyyyfuXTFQgSJvfT8GMZ0uRJr4dN/jHyLfn8bz856dq/u0xQCWXeZj1E4KvmK/ss9GZpsx53p94vMjb16ypZZ5AnFQ8dR+ELdbDv3bgPTakRmQ9lRdJ6jiu6Z2wUhuz6cyiMKl" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:18 volumio go-librespot[2363]: time="2025-03-10T09:03:18+11:00" level=debug msg="completed challenge" Mar 10 09:03:19 volumio go-librespot[2363]: time="2025-03-10T09:03:19+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:19 volumio volumio[1065]: info: Connection to go-librespot Websocket closed Mar 10 09:03:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:20 volumio volumio[1065]: info: Executing endpoint metavolumio Mar 10 09:03:20 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 10 09:03:20 volumio volumio[1065]: info: Executing endpoint metavolumio Mar 10 09:03:20 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 10 09:03:21 volumio volumio[1065]: info: Getting Spotify volume Mar 10 09:03:21 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:21 volumio volumio[1065]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Mar 10 09:03:21 volumio volumio[1065]: (node:1065) 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: 25) Mar 10 09:03:21 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Mar 10 09:03:21 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState Mar 10 09:03:21 volumio volumio[1065]: info: CorePlayQueue::getTrack 2 Mar 10 09:03:21 volumio volumio[1065]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 10 09:03:22 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:22 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:22 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 76. Mar 10 09:03:22 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:22 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:22 volumio go-librespot[2372]: go-librespot daemon starting... Mar 10 09:03:22 volumio go-librespot[2372]: time="2025-03-10T09:03:22+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:22 volumio go-librespot[2372]: time="2025-03-10T09:03:22+11:00" level=debug msg="app state loaded" Mar 10 09:03:22 volumio go-librespot[2372]: time="2025-03-10T09:03:22+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:22 volumio go-librespot[2372]: time="2025-03-10T09:03:22+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:22 volumio go-librespot[2372]: time="2025-03-10T09:03:22+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:22 volumio go-librespot[2372]: time="2025-03-10T09:03:22+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:22 volumio go-librespot[2372]: time="2025-03-10T09:03:22+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:22 volumio go-librespot[2372]: time="2025-03-10T09:03:22+11:00" level=info msg="zeroconf server listening on port 42869" Mar 10 09:03:22 volumio go-librespot[2372]: time="2025-03-10T09:03:22+11:00" level=debug msg="obtained new client token: AACTr2MU13IOM+tgqZx90ho4xSDUNr5XUvL0nlf1ZHdtON62zaS69SsiJdn1OqcKJnDyz9BFEMZsR5OyI2ivdVyPeBlKOuY93yQe1HrJwOFqe2fyT0weKS495FSm7+PTJ+e4X5sM58+zV1wPs4tdq5F27SEN+nK35Gv29D3mBMa1ipsWqbeElpRAAE43NxtNjNtoCMXwgZbGsLzH4A8zLmr7XFJxLl8Aj4pWT2rY9s7X02Bziob6PSSiOOHC" Mar 10 09:03:23 volumio go-librespot[2372]: time="2025-03-10T09:03:23+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:23 volumio go-librespot[2372]: time="2025-03-10T09:03:23+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:23 volumio go-librespot[2372]: time="2025-03-10T09:03:23+11:00" level=debug msg="completed challenge" Mar 10 09:03:23 volumio go-librespot[2372]: time="2025-03-10T09:03:23+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:25 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:25 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:26 volumio volumio[1065]: info: Preload queue cleared Mar 10 09:03:26 volumio volumio[1065]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::ClearQueue Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::stop Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 10 09:03:26 volumio volumio[1065]: info: CorePlayQueue::clearPlayQueue Mar 10 09:03:26 volumio volumio[1065]: info: CorePlayQueue::saveQueue Mar 10 09:03:26 volumio volumio[1065]: info: CoreCommandRouter::volumioPushQueue Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::addQueueItems Mar 10 09:03:26 volumio volumio[1065]: info: CorePlayQueue::addQueueItems Mar 10 09:03:26 volumio volumio[1065]: info: Preload queue cleared Mar 10 09:03:26 volumio volumio[1065]: info: Adding Item to queue: spotify:track:2faOZdGGcTeNkej0P9ZdVS Mar 10 09:03:26 volumio volumio[1065]: info: Exploding uri spotify:track:2faOZdGGcTeNkej0P9ZdVS in service spop Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: EXPLODING URI:spotify:track:2faOZdGGcTeNkej0P9ZdVS Mar 10 09:03:26 volumio volumio[1065]: info: Adding Item to queue: spotify:track:4DNyKoJBdTpLnA3ryWL7Qh Mar 10 09:03:26 volumio volumio[1065]: info: Exploding uri spotify:track:4DNyKoJBdTpLnA3ryWL7Qh in service spop Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: EXPLODING URI:spotify:track:4DNyKoJBdTpLnA3ryWL7Qh Mar 10 09:03:26 volumio volumio[1065]: info: Adding Item to queue: spotify:track:57WPJyUY4nMbWFMLRL0dev Mar 10 09:03:26 volumio volumio[1065]: info: Exploding uri spotify:track:57WPJyUY4nMbWFMLRL0dev in service spop Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: EXPLODING URI:spotify:track:57WPJyUY4nMbWFMLRL0dev Mar 10 09:03:26 volumio volumio[1065]: info: Adding Item to queue: spotify:track:2HI9RNrsgIqqqrX46atCiz Mar 10 09:03:26 volumio volumio[1065]: info: Exploding uri spotify:track:2HI9RNrsgIqqqrX46atCiz in service spop Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: EXPLODING URI:spotify:track:2HI9RNrsgIqqqrX46atCiz Mar 10 09:03:26 volumio volumio[1065]: info: Adding Item to queue: spotify:track:7hchxAnI7eRlUKIWdjzGDr Mar 10 09:03:26 volumio volumio[1065]: info: Exploding uri spotify:track:7hchxAnI7eRlUKIWdjzGDr in service spop Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: EXPLODING URI:spotify:track:7hchxAnI7eRlUKIWdjzGDr Mar 10 09:03:26 volumio volumio[1065]: info: Adding Item to queue: spotify:track:2UIpEVOcvD4fnrUAITs94P Mar 10 09:03:26 volumio volumio[1065]: info: Exploding uri spotify:track:2UIpEVOcvD4fnrUAITs94P in service spop Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: EXPLODING URI:spotify:track:2UIpEVOcvD4fnrUAITs94P Mar 10 09:03:26 volumio volumio[1065]: info: Adding Item to queue: spotify:track:1oa9uCf1yjhZqpqBddoNJs Mar 10 09:03:26 volumio volumio[1065]: info: Exploding uri spotify:track:1oa9uCf1yjhZqpqBddoNJs in service spop Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: EXPLODING URI:spotify:track:1oa9uCf1yjhZqpqBddoNJs Mar 10 09:03:26 volumio volumio[1065]: info: Adding Item to queue: spotify:track:01uVlNzTTFLpxRnEvJeBBL Mar 10 09:03:26 volumio volumio[1065]: info: Exploding uri spotify:track:01uVlNzTTFLpxRnEvJeBBL in service spop Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: EXPLODING URI:spotify:track:01uVlNzTTFLpxRnEvJeBBL Mar 10 09:03:26 volumio volumio[1065]: info: Adding Item to queue: spotify:track:5eemER42XxQkSw3MJgYuhK Mar 10 09:03:26 volumio volumio[1065]: info: Exploding uri spotify:track:5eemER42XxQkSw3MJgYuhK in service spop Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: EXPLODING URI:spotify:track:5eemER42XxQkSw3MJgYuhK Mar 10 09:03:26 volumio volumio[1065]: info: Adding Item to queue: spotify:track:2KmEauRbv5XfiUFjZpvPUK Mar 10 09:03:26 volumio volumio[1065]: info: Exploding uri spotify:track:2KmEauRbv5XfiUFjZpvPUK in service spop Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: EXPLODING URI:spotify:track:2KmEauRbv5XfiUFjZpvPUK Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4DNyKoJBdTpLnA3ryWL7Qh","service":"spop","name":"Take Me Home (feat. Nadia Reid)","artist":"The Paper Kites","album":"Roses","type":"song","duration":294,"albumart":"https://i.scdn.co/image/ab67616d0000b2733cfd2700010422367b516305","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2faOZdGGcTeNkej0P9ZdVS","service":"spop","name":"Baby Bright","artist":"Nadia Reid","album":"Enter Now Brightness","type":"song","duration":232,"albumart":"https://i.scdn.co/image/ab67616d0000b2732598e0032a2e446c21957698","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:57WPJyUY4nMbWFMLRL0dev","service":"spop","name":"Call the Days","artist":"Nadia Reid","album":"Listen to Formation, Look for the Signs","type":"song","duration":212,"albumart":"https://i.scdn.co/image/ab67616d0000b273fb021ca5ca0fa919952d5a39","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2HI9RNrsgIqqqrX46atCiz","service":"spop","name":"Hold It Up","artist":"Nadia Reid","album":"Enter Now Brightness","type":"song","duration":247,"albumart":"https://i.scdn.co/image/ab67616d0000b2732598e0032a2e446c21957698","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2UIpEVOcvD4fnrUAITs94P","service":"spop","name":"Ruby","artist":"Nadia Reid","album":"Listen to Formation, Look for the Signs","type":"song","duration":215,"albumart":"https://i.scdn.co/image/ab67616d0000b273fb021ca5ca0fa919952d5a39","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7hchxAnI7eRlUKIWdjzGDr","service":"spop","name":"Runway","artist":"Nadia Reid","album":"Listen to Formation, Look for the Signs","type":"song","duration":193,"albumart":"https://i.scdn.co/image/ab67616d0000b273fb021ca5ca0fa919952d5a39","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:01uVlNzTTFLpxRnEvJeBBL","service":"spop","name":"Send It Down The Line","artist":"Nadia Reid","album":"Enter Now Brightness","type":"song","duration":308,"albumart":"https://i.scdn.co/image/ab67616d0000b2732598e0032a2e446c21957698","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5eemER42XxQkSw3MJgYuhK","service":"spop","name":"Emmanuelle","artist":"Nadia Reid","album":"Enter Now Brightness","type":"song","duration":213,"albumart":"https://i.scdn.co/image/ab67616d0000b2732598e0032a2e446c21957698","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1oa9uCf1yjhZqpqBddoNJs","service":"spop","name":"Holy Low","artist":"Nadia Reid","album":"Listen to Formation, Look for the Signs","type":"song","duration":219,"albumart":"https://i.scdn.co/image/ab67616d0000b273fb021ca5ca0fa919952d5a39","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 10 09:03:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 77. Mar 10 09:03:26 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:26 volumio volumio[1065]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2KmEauRbv5XfiUFjZpvPUK","service":"spop","name":"Just to Feel Alive","artist":"Nadia Reid","album":"Listen to Formation, Look for the Signs","type":"song","duration":233,"albumart":"https://i.scdn.co/image/ab67616d0000b273fb021ca5ca0fa919952d5a39","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 10 09:03:26 volumio volumio[1065]: info: CoreCommandRouter::volumioPushQueue Mar 10 09:03:26 volumio volumio[1065]: info: CorePlayQueue::saveQueue Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::updateTrackBlock Mar 10 09:03:26 volumio volumio[1065]: info: CorePlayQueue::getTrackBlock Mar 10 09:03:26 volumio volumio[1065]: info: CoreCommandRouter::volumioPlay Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::play index 0 Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::stop Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::play index undefined Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 10 09:03:26 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:26 volumio volumio[1065]: info: CoreStateMachine::startPlaybackTimer Mar 10 09:03:26 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:26 volumio volumio[1065]: info: [1741557806532] ControllerSpotify::clearAddPlayTrack Mar 10 09:03:26 volumio volumio[1065]: info: Sending Spotify command with payload to local API: /player/play Mar 10 09:03:26 volumio volumio[1065]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:26 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:26 volumio go-librespot[2380]: go-librespot daemon starting... Mar 10 09:03:26 volumio go-librespot[2380]: time="2025-03-10T09:03:26+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:26 volumio go-librespot[2380]: time="2025-03-10T09:03:26+11:00" level=debug msg="app state loaded" Mar 10 09:03:26 volumio go-librespot[2380]: time="2025-03-10T09:03:26+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:26 volumio go-librespot[2380]: time="2025-03-10T09:03:26+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:26 volumio go-librespot[2380]: time="2025-03-10T09:03:26+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:26 volumio go-librespot[2380]: time="2025-03-10T09:03:26+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:26 volumio go-librespot[2380]: time="2025-03-10T09:03:26+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:26 volumio go-librespot[2380]: time="2025-03-10T09:03:26+11:00" level=info msg="zeroconf server listening on port 41277" Mar 10 09:03:27 volumio go-librespot[2380]: time="2025-03-10T09:03:27+11:00" level=debug msg="obtained new client token: AAD4hJxRU/17OGvSVfcD0ex71MRRPpcIpsSHJ1sZ9eF2NVZZ6muRDLiSxods2CVO/olLsgmqnM38kZC9cyPnp20GTxh2Ae7zzK3MEJNeBgH5mR3LWE87EUJPRQfc+rS5N0anQKNZ2pRh81uXY5sre0cp35XkY4hpl51GpA/CYFVd9a90MoqtIaVCXgo8yPRTnsmxVn9C59nqNg8IZ8Q7CsnStbjqmxUQ+VqF8Jpb06hZOiGRs4mHITmpug==" Mar 10 09:03:27 volumio go-librespot[2380]: time="2025-03-10T09:03:27+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:27 volumio go-librespot[2380]: time="2025-03-10T09:03:27+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:27 volumio go-librespot[2380]: time="2025-03-10T09:03:27+11:00" level=debug msg="completed challenge" Mar 10 09:03:27 volumio go-librespot[2380]: time="2025-03-10T09:03:27+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:27 volumio volumio[1065]: info: Preload queue cleared Mar 10 09:03:27 volumio volumio[1065]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::ClearQueue Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::stop Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 10 09:03:27 volumio volumio[1065]: info: CorePlayQueue::clearPlayQueue Mar 10 09:03:27 volumio volumio[1065]: info: CorePlayQueue::saveQueue Mar 10 09:03:27 volumio volumio[1065]: info: CoreCommandRouter::volumioPushQueue Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::addQueueItems Mar 10 09:03:27 volumio volumio[1065]: info: CorePlayQueue::addQueueItems Mar 10 09:03:27 volumio volumio[1065]: info: Preload queue cleared Mar 10 09:03:27 volumio volumio[1065]: info: Adding Item to queue: spotify:track:2faOZdGGcTeNkej0P9ZdVS Mar 10 09:03:27 volumio volumio[1065]: info: Using cached record of: spotify:track:2faOZdGGcTeNkej0P9ZdVS Mar 10 09:03:27 volumio volumio[1065]: info: Adding Item to queue: spotify:track:4DNyKoJBdTpLnA3ryWL7Qh Mar 10 09:03:27 volumio volumio[1065]: info: Using cached record of: spotify:track:4DNyKoJBdTpLnA3ryWL7Qh Mar 10 09:03:27 volumio volumio[1065]: info: Adding Item to queue: spotify:track:57WPJyUY4nMbWFMLRL0dev Mar 10 09:03:27 volumio volumio[1065]: info: Using cached record of: spotify:track:57WPJyUY4nMbWFMLRL0dev Mar 10 09:03:27 volumio volumio[1065]: info: Adding Item to queue: spotify:track:2HI9RNrsgIqqqrX46atCiz Mar 10 09:03:27 volumio volumio[1065]: info: Using cached record of: spotify:track:2HI9RNrsgIqqqrX46atCiz Mar 10 09:03:27 volumio volumio[1065]: info: Adding Item to queue: spotify:track:7hchxAnI7eRlUKIWdjzGDr Mar 10 09:03:27 volumio volumio[1065]: info: Using cached record of: spotify:track:7hchxAnI7eRlUKIWdjzGDr Mar 10 09:03:27 volumio volumio[1065]: info: Adding Item to queue: spotify:track:2UIpEVOcvD4fnrUAITs94P Mar 10 09:03:27 volumio volumio[1065]: info: Using cached record of: spotify:track:2UIpEVOcvD4fnrUAITs94P Mar 10 09:03:27 volumio volumio[1065]: info: Adding Item to queue: spotify:track:1oa9uCf1yjhZqpqBddoNJs Mar 10 09:03:27 volumio volumio[1065]: info: Using cached record of: spotify:track:1oa9uCf1yjhZqpqBddoNJs Mar 10 09:03:27 volumio volumio[1065]: info: Adding Item to queue: spotify:track:01uVlNzTTFLpxRnEvJeBBL Mar 10 09:03:27 volumio volumio[1065]: info: Using cached record of: spotify:track:01uVlNzTTFLpxRnEvJeBBL Mar 10 09:03:27 volumio volumio[1065]: info: Adding Item to queue: spotify:track:5eemER42XxQkSw3MJgYuhK Mar 10 09:03:27 volumio volumio[1065]: info: Using cached record of: spotify:track:5eemER42XxQkSw3MJgYuhK Mar 10 09:03:27 volumio volumio[1065]: info: Adding Item to queue: spotify:track:2KmEauRbv5XfiUFjZpvPUK Mar 10 09:03:27 volumio volumio[1065]: info: Using cached record of: spotify:track:2KmEauRbv5XfiUFjZpvPUK Mar 10 09:03:27 volumio volumio[1065]: info: CoreCommandRouter::volumioPushQueue Mar 10 09:03:27 volumio volumio[1065]: info: CorePlayQueue::saveQueue Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::updateTrackBlock Mar 10 09:03:27 volumio volumio[1065]: info: CorePlayQueue::getTrackBlock Mar 10 09:03:27 volumio volumio[1065]: info: CoreCommandRouter::volumioPlay Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::play index 0 Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::stop Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::play index undefined Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 10 09:03:27 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:27 volumio volumio[1065]: info: CoreStateMachine::startPlaybackTimer Mar 10 09:03:27 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:27 volumio volumio[1065]: info: [1741557807907] ControllerSpotify::clearAddPlayTrack Mar 10 09:03:27 volumio volumio[1065]: info: Sending Spotify command with payload to local API: /player/play Mar 10 09:03:27 volumio volumio[1065]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:28 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:28 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 78. Mar 10 09:03:30 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:30 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:30 volumio go-librespot[2427]: go-librespot daemon starting... Mar 10 09:03:30 volumio go-librespot[2427]: time="2025-03-10T09:03:30+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:30 volumio go-librespot[2427]: time="2025-03-10T09:03:30+11:00" level=debug msg="app state loaded" Mar 10 09:03:30 volumio go-librespot[2427]: time="2025-03-10T09:03:30+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:30 volumio go-librespot[2427]: time="2025-03-10T09:03:30+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:31 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:31 volumio go-librespot[2427]: time="2025-03-10T09:03:31+11:00" level=debug msg="new websocket client" Mar 10 09:03:31 volumio volumio[1065]: info: Connection to go-librespot Websocket established Mar 10 09:03:31 volumio go-librespot[2427]: time="2025-03-10T09:03:31+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:31 volumio go-librespot[2427]: time="2025-03-10T09:03:31+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:31 volumio go-librespot[2427]: time="2025-03-10T09:03:31+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:31 volumio go-librespot[2427]: time="2025-03-10T09:03:31+11:00" level=info msg="zeroconf server listening on port 42305" Mar 10 09:03:31 volumio go-librespot[2427]: time="2025-03-10T09:03:31+11:00" level=debug msg="obtained new client token: AACUUMmbzuxQs0HEj9EIUmFrZkX5IXOY/izMS4C5bwQGKRFcIebY3oZp2Dkq7wpXbC4BYjqRg3CUu+7INrSeVtKz3p1ZIPAu+f0AyCG7Qq72+OMeRNo/oHmPtiDdeB2aMxCHbHvoXurUcPOCtIf2hSIdWsvNVNuY2WqMVLsTloAjMY3tJpxNlfHbgRf1sNe2RyniwVvqzP4t5p9prsvNSjN+LJY5LG4lxKv891hny9DJqFlc+YqN5xZMmNeh" Mar 10 09:03:31 volumio go-librespot[2427]: time="2025-03-10T09:03:31+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:31 volumio go-librespot[2427]: time="2025-03-10T09:03:31+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:31 volumio go-librespot[2427]: time="2025-03-10T09:03:31+11:00" level=debug msg="completed challenge" Mar 10 09:03:31 volumio go-librespot[2427]: time="2025-03-10T09:03:31+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:31 volumio volumio[1065]: info: Connection to go-librespot Websocket closed Mar 10 09:03:33 volumio volumio[1065]: info: CoreCommandRouter::volumioPlay Mar 10 09:03:33 volumio volumio[1065]: info: CoreStateMachine::play index undefined Mar 10 09:03:33 volumio volumio[1065]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 10 09:03:33 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:33 volumio volumio[1065]: info: CoreStateMachine::startPlaybackTimer Mar 10 09:03:33 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:33 volumio volumio[1065]: info: [1741557813283] ControllerSpotify::clearAddPlayTrack Mar 10 09:03:33 volumio volumio[1065]: info: Sending Spotify command with payload to local API: /player/play Mar 10 09:03:33 volumio volumio[1065]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:34 volumio volumio[1065]: info: Getting Spotify volume Mar 10 09:03:34 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:34 volumio volumio[1065]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Mar 10 09:03:34 volumio volumio[1065]: (node:1065) 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: 26) Mar 10 09:03:34 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Mar 10 09:03:34 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState Mar 10 09:03:34 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:34 volumio volumio[1065]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 10 09:03:34 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:34 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:34 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 79. Mar 10 09:03:34 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:35 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:35 volumio go-librespot[2437]: go-librespot daemon starting... Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=debug msg="app state loaded" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=info msg="zeroconf server listening on port 44321" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=debug msg="obtained new client token: AACycCiBuLNjyZdgumbjj3dMncigY6pwwwAZHvni20+OQsN9laFinVXGHpTcVmfoSw3moQgixW0KLFozdBUJ6il7IGoqIpBO4Ndw/hLw6751Y7VG58+YcjWtl0ocew9VXXhsJap04pifng/GSgTAifR9hjoFICVIaBmIo1BpmlHVNxm0oXGVLgsHn5RhZ/3kd8eHnuVjzIWh+jRhBLwEtTB3+PRIvhZ6IEKhLfJ0ssk6zwEktsQBhaYCGrkG" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:35 volumio go-librespot[2437]: time="2025-03-10T09:03:35+11:00" level=debug msg="completed challenge" Mar 10 09:03:36 volumio go-librespot[2437]: time="2025-03-10T09:03:36+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:37 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:37 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 80. Mar 10 09:03:39 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:39 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:39 volumio go-librespot[2445]: go-librespot daemon starting... Mar 10 09:03:39 volumio go-librespot[2445]: time="2025-03-10T09:03:39+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:39 volumio go-librespot[2445]: time="2025-03-10T09:03:39+11:00" level=debug msg="app state loaded" Mar 10 09:03:39 volumio go-librespot[2445]: time="2025-03-10T09:03:39+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:39 volumio go-librespot[2445]: time="2025-03-10T09:03:39+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:39 volumio go-librespot[2445]: time="2025-03-10T09:03:39+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:39 volumio go-librespot[2445]: time="2025-03-10T09:03:39+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:39 volumio go-librespot[2445]: time="2025-03-10T09:03:39+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:39 volumio go-librespot[2445]: time="2025-03-10T09:03:39+11:00" level=info msg="zeroconf server listening on port 45809" Mar 10 09:03:39 volumio go-librespot[2445]: time="2025-03-10T09:03:39+11:00" level=debug msg="obtained new client token: AADuW5nydXk0OX6q/VNQKM8Vmnb6GFGscvrP+F47SwaTHwIMGi/7jyTK3MR22YzCcsUMwdxkH8u9fKWBkTPyBc/LiZWhG6WdYfQTrq/ViUlGF7csqo2yd0Ll1aITrvqTye8E6Wjuw7v00INxyDURBV47/l+VBB7s+3ArP2OLxtYk7sjs7OprWVvcstpGYZdda5NnN4nIRKE6YwxQQJhHSS1aTItrdUL7S1PgaofpQT1fFAHYN7HgzJOlZiZv" Mar 10 09:03:40 volumio go-librespot[2445]: time="2025-03-10T09:03:40+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:40 volumio go-librespot[2445]: time="2025-03-10T09:03:40+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:40 volumio go-librespot[2445]: time="2025-03-10T09:03:40+11:00" level=debug msg="completed challenge" Mar 10 09:03:40 volumio go-librespot[2445]: time="2025-03-10T09:03:40+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:40 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:40 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 81. Mar 10 09:03:43 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:43 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:43 volumio go-librespot[2453]: go-librespot daemon starting... Mar 10 09:03:43 volumio go-librespot[2453]: time="2025-03-10T09:03:43+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:43 volumio go-librespot[2453]: time="2025-03-10T09:03:43+11:00" level=debug msg="app state loaded" Mar 10 09:03:43 volumio go-librespot[2453]: time="2025-03-10T09:03:43+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:43 volumio go-librespot[2453]: time="2025-03-10T09:03:43+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:43 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:43 volumio go-librespot[2453]: time="2025-03-10T09:03:43+11:00" level=debug msg="new websocket client" Mar 10 09:03:43 volumio volumio[1065]: info: Connection to go-librespot Websocket established Mar 10 09:03:43 volumio go-librespot[2453]: time="2025-03-10T09:03:43+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 10 09:03:43 volumio go-librespot[2453]: time="2025-03-10T09:03:43+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 10 09:03:43 volumio go-librespot[2453]: time="2025-03-10T09:03:43+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 10 09:03:43 volumio go-librespot[2453]: time="2025-03-10T09:03:43+11:00" level=info msg="zeroconf server listening on port 45309" Mar 10 09:03:44 volumio go-librespot[2453]: time="2025-03-10T09:03:44+11:00" level=debug msg="obtained new client token: AACja4FIo9nE45cHnPQlsZNWZbOuNVAPbZeHy7LjAm2xh8K3j5seFjQIFq0DgWaoH5sE7MyJB1zU+hAh1LpXkjbJlwYJJMUb+f0wXD6ZGjV0IsMz6dasOgfSB7wQ8f0ISa5qztmBzIRN9PBnc8RDie912JZYDPhtaadRsYEG65Q46voQEtydG0+/11gIUm2FaNPr2lbIjjw9JxvuSFHNo0y8h145GUwNRrEt0IEsW7KDnD2LWbJO3Fxxqw==" Mar 10 09:03:44 volumio go-librespot[2453]: time="2025-03-10T09:03:44+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:44 volumio go-librespot[2453]: time="2025-03-10T09:03:44+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:44 volumio go-librespot[2453]: time="2025-03-10T09:03:44+11:00" level=debug msg="completed challenge" Mar 10 09:03:44 volumio go-librespot[2453]: time="2025-03-10T09:03:44+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:44 volumio volumio[1065]: info: Connection to go-librespot Websocket closed Mar 10 09:03:46 volumio volumio[1065]: info: Getting Spotify volume Mar 10 09:03:46 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:46 volumio volumio[1065]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Mar 10 09:03:46 volumio volumio[1065]: (node:1065) 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: 27) Mar 10 09:03:46 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 10 09:03:46 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState Mar 10 09:03:46 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:46 volumio volumio[1065]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 10 09:03:47 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:47 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 82. Mar 10 09:03:47 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:47 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:47 volumio go-librespot[2461]: go-librespot daemon starting... Mar 10 09:03:47 volumio go-librespot[2461]: time="2025-03-10T09:03:47+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:47 volumio go-librespot[2461]: time="2025-03-10T09:03:47+11:00" level=debug msg="app state loaded" Mar 10 09:03:47 volumio go-librespot[2461]: time="2025-03-10T09:03:47+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:47 volumio go-librespot[2461]: time="2025-03-10T09:03:47+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:48 volumio go-librespot[2461]: time="2025-03-10T09:03:48+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:48 volumio go-librespot[2461]: time="2025-03-10T09:03:48+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:48 volumio go-librespot[2461]: time="2025-03-10T09:03:48+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:48 volumio go-librespot[2461]: time="2025-03-10T09:03:48+11:00" level=info msg="zeroconf server listening on port 33933" Mar 10 09:03:48 volumio go-librespot[2461]: time="2025-03-10T09:03:48+11:00" level=debug msg="obtained new client token: AACZgA1e+QSV0wIEdqhTsbLgAaQYxY+6oSDr0r7kT/Akmrq9upr8cC8PnuVOiawOXvf7DLpWIaxb0SX2+vn+6OWSawd8JhXHdtmJAjGZitTNgv/PfW9exbtASVWOI2q4JmcCAe4eWv1x14KoXIjMeTouSQDY0/p7e1IMqRVnnYnbi+HQC5WPPCwVLrdEVju8qCJM1guSgIqolfPiexppCM5APNHkoiJm0lgPRRvYIre6OAglOwqMTWPNyLCY" Mar 10 09:03:48 volumio go-librespot[2461]: time="2025-03-10T09:03:48+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:48 volumio go-librespot[2461]: time="2025-03-10T09:03:48+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:48 volumio go-librespot[2461]: time="2025-03-10T09:03:48+11:00" level=debug msg="completed challenge" Mar 10 09:03:48 volumio go-librespot[2461]: time="2025-03-10T09:03:48+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:49 volumio volumio[1065]: info: CoreCommandRouter::volumioPlay Mar 10 09:03:49 volumio volumio[1065]: info: CoreStateMachine::play index undefined Mar 10 09:03:49 volumio volumio[1065]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 10 09:03:49 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:49 volumio volumio[1065]: info: CoreStateMachine::startPlaybackTimer Mar 10 09:03:49 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:49 volumio volumio[1065]: info: [1741557829303] ControllerSpotify::clearAddPlayTrack Mar 10 09:03:49 volumio volumio[1065]: info: Sending Spotify command with payload to local API: /player/play Mar 10 09:03:49 volumio volumio[1065]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:50 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:50 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 83. Mar 10 09:03:51 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:52 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:52 volumio go-librespot[2469]: go-librespot daemon starting... Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=debug msg="app state loaded" Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=info msg="zeroconf server listening on port 41123" Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=debug msg="obtained new client token: AAAS1ZioWBmJrqWIDk0DDgJE5ZLBk8+agvPZ7MaXIeg6azdBR0qZ+28tfAkVgCSvuWhS3IAiu54tAEqsahe2tZeAqLwEbr0UHypcEZW+Uvq8VXh64JQuJh0vr31/O5aMhmX8sSmlxLs3GbMs6ipS22garMtjlxA6et66BguDb9hQRXS5njZcDFjK35v919SdsMIeqqAtpJ8gQTZS/DHqcB+4KtZ6GHp1RPpAW6haXFKy3gzx8opm9sSJ6ejI" Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Mar 10 09:03:52 volumio go-librespot[2469]: time="2025-03-10T09:03:52+11:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 10 09:03:53 volumio go-librespot[2469]: time="2025-03-10T09:03:53+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:53 volumio go-librespot[2469]: time="2025-03-10T09:03:53+11:00" level=debug msg="completed challenge" Mar 10 09:03:53 volumio go-librespot[2469]: time="2025-03-10T09:03:53+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:53 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:53 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:56 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:03:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 84. Mar 10 09:03:56 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:03:56 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:03:56 volumio go-librespot[2479]: go-librespot daemon starting... Mar 10 09:03:56 volumio go-librespot[2479]: time="2025-03-10T09:03:56+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:03:56 volumio go-librespot[2479]: time="2025-03-10T09:03:56+11:00" level=debug msg="app state loaded" Mar 10 09:03:56 volumio go-librespot[2479]: time="2025-03-10T09:03:56+11:00" level=debug msg="stored credentials not found" Mar 10 09:03:56 volumio go-librespot[2479]: time="2025-03-10T09:03:56+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:03:56 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:03:56 volumio go-librespot[2479]: time="2025-03-10T09:03:56+11:00" level=debug msg="new websocket client" Mar 10 09:03:56 volumio volumio[1065]: info: Connection to go-librespot Websocket established Mar 10 09:03:56 volumio go-librespot[2479]: time="2025-03-10T09:03:56+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 10 09:03:56 volumio go-librespot[2479]: time="2025-03-10T09:03:56+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 10 09:03:56 volumio go-librespot[2479]: time="2025-03-10T09:03:56+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 10 09:03:56 volumio go-librespot[2479]: time="2025-03-10T09:03:56+11:00" level=info msg="zeroconf server listening on port 36583" Mar 10 09:03:56 volumio go-librespot[2479]: time="2025-03-10T09:03:56+11:00" level=debug msg="obtained new client token: AAB/r2n5O/CEMzfkHq/b0jpeRCIAEtv1qfGPQiL/jpxJ3MkhE0ocd36kFzVyYi+MPAWVO1zk3Ujc/gIxWBkWTCH+uHfBYN7X5ENoOAdHW/3PVjxbTQnEfyXFJvK39fJSbIi9cxoTDoNWDuQoSBRpjVJ5LAl3e+TANy4ab+FumL0Tmi3+jXAbFuJrU0dVFxbOVmtrdnpk4JgntaE232uDU6wPmLnpCujBDVcpJ+cAvgYmX1JxcGYSm/rhUeUc" Mar 10 09:03:57 volumio go-librespot[2479]: time="2025-03-10T09:03:57+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:03:57 volumio go-librespot[2479]: time="2025-03-10T09:03:57+11:00" level=debug msg="completed keyexchange" Mar 10 09:03:57 volumio go-librespot[2479]: time="2025-03-10T09:03:57+11:00" level=debug msg="completed challenge" Mar 10 09:03:57 volumio go-librespot[2479]: time="2025-03-10T09:03:57+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:03:57 volumio volumio[1065]: info: Connection to go-librespot Websocket closed Mar 10 09:03:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:03:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:03:59 volumio volumio[1065]: info: Getting Spotify volume Mar 10 09:03:59 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:03:59 volumio volumio[1065]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Mar 10 09:03:59 volumio volumio[1065]: (node:1065) 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: 28) Mar 10 09:03:59 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 10 09:03:59 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState Mar 10 09:03:59 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:03:59 volumio volumio[1065]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 10 09:04:00 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:00 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:04:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 85. Mar 10 09:04:00 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:04:00 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:04:00 volumio go-librespot[2487]: go-librespot daemon starting... Mar 10 09:04:00 volumio go-librespot[2487]: time="2025-03-10T09:04:00+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:04:00 volumio go-librespot[2487]: time="2025-03-10T09:04:00+11:00" level=debug msg="app state loaded" Mar 10 09:04:00 volumio go-librespot[2487]: time="2025-03-10T09:04:00+11:00" level=debug msg="stored credentials not found" Mar 10 09:04:00 volumio go-librespot[2487]: time="2025-03-10T09:04:00+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:04:00 volumio go-librespot[2487]: time="2025-03-10T09:04:00+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:04:00 volumio go-librespot[2487]: time="2025-03-10T09:04:00+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:04:00 volumio go-librespot[2487]: time="2025-03-10T09:04:00+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:04:00 volumio go-librespot[2487]: time="2025-03-10T09:04:00+11:00" level=info msg="zeroconf server listening on port 42175" Mar 10 09:04:01 volumio go-librespot[2487]: time="2025-03-10T09:04:01+11:00" level=debug msg="obtained new client token: AADgmXiPPrrz8VyRG3fuVOqRd70JnMf+w9bhNGblAAFYDILO2tA8sPjLNKSXrpU1D4t3TkUCpQ3BDeUTEDQU00AFxnk9yuS5DVV7dq6OPP/H8eZZfnm+F/pbBUjSOFjLr8PNkPRZutPoUt0C7m6QQbRKRx+o54l8wxqQlhUtgxBAcMuwubmuexFRZxo/egcialoP5NTMl9n83h20LqfAP5K7khZSO3Ur8P57mj/hF9kPmdVkRMDDWNAlVA==" Mar 10 09:04:01 volumio go-librespot[2487]: time="2025-03-10T09:04:01+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:04:01 volumio go-librespot[2487]: time="2025-03-10T09:04:01+11:00" level=debug msg="completed keyexchange" Mar 10 09:04:01 volumio go-librespot[2487]: time="2025-03-10T09:04:01+11:00" level=debug msg="completed challenge" Mar 10 09:04:01 volumio go-librespot[2487]: time="2025-03-10T09:04:01+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:04:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:04:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:04:03 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:03 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:04 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:04:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 86. Mar 10 09:04:04 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:04:04 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:04:04 volumio go-librespot[2495]: go-librespot daemon starting... Mar 10 09:04:04 volumio go-librespot[2495]: time="2025-03-10T09:04:04+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:04:04 volumio go-librespot[2495]: time="2025-03-10T09:04:04+11:00" level=debug msg="app state loaded" Mar 10 09:04:04 volumio go-librespot[2495]: time="2025-03-10T09:04:04+11:00" level=debug msg="stored credentials not found" Mar 10 09:04:04 volumio go-librespot[2495]: time="2025-03-10T09:04:04+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:04:05 volumio go-librespot[2495]: time="2025-03-10T09:04:05+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:04:05 volumio go-librespot[2495]: time="2025-03-10T09:04:05+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:04:05 volumio go-librespot[2495]: time="2025-03-10T09:04:05+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:04:05 volumio go-librespot[2495]: time="2025-03-10T09:04:05+11:00" level=info msg="zeroconf server listening on port 42743" Mar 10 09:04:05 volumio go-librespot[2495]: time="2025-03-10T09:04:05+11:00" level=debug msg="obtained new client token: AADK0/PP0s94z9nINq8Nkn9UGFnuBUtN5neWgAZ0ET/pV2PWSbDJdeA2rvDDHT6EIGrjw5x2oB/wa1RYym6XXfmit0O6UWkNDOi+yTpaOszIJzSl5FodHthNeGJrPVg5ksKCTa4hfpOg0dVgsxn3c2DgJyX8oViqu9RdJ+SXgu20rqZ7ws8hbwuQlUfaLyyG606B9aP+ufqrLfwZk4UxAD4KLa1BP5vXXjJi2zGjdvheKJy5xDsKLYJJBCdR" Mar 10 09:04:05 volumio go-librespot[2495]: time="2025-03-10T09:04:05+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:04:05 volumio go-librespot[2495]: time="2025-03-10T09:04:05+11:00" level=debug msg="completed keyexchange" Mar 10 09:04:05 volumio go-librespot[2495]: time="2025-03-10T09:04:05+11:00" level=debug msg="completed challenge" Mar 10 09:04:05 volumio go-librespot[2495]: time="2025-03-10T09:04:05+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:04:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:04:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:04:06 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:06 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:04:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 87. Mar 10 09:04:08 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:04:09 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:04:09 volumio go-librespot[2505]: go-librespot daemon starting... Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=debug msg="app state loaded" Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=debug msg="stored credentials not found" Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:04:09 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=debug msg="new websocket client" Mar 10 09:04:09 volumio volumio[1065]: info: Connection to go-librespot Websocket established Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=info msg="zeroconf server listening on port 32899" Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=debug msg="obtained new client token: AABAGLf3zhFcdoNONVWwmI3xk28r4zI/UtGL3sz7Hz5W9KCXkK+7Hft5q/C1XZEzrYqJFPrWqsa4ikbYHl9ma33WpTK61Zm/JHYBRjbmZkDnTGEJzn74jY619a02c/oILmd78KlhPP8+2LKK8ZJ2JRq7927AE0VxCAup6llGKfHT0kfuTmgO+d58zohRWagnM8c/m6VGAhSAjB/UP1LMU6wtP/8XUg8saNau5a0xgjQFA0kVn3ZUoRlbqqYk" Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=debug msg="completed keyexchange" Mar 10 09:04:09 volumio go-librespot[2505]: time="2025-03-10T09:04:09+11:00" level=debug msg="completed challenge" Mar 10 09:04:10 volumio go-librespot[2505]: time="2025-03-10T09:04:10+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:04:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:04:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:04:10 volumio volumio[1065]: info: Connection to go-librespot Websocket closed Mar 10 09:04:12 volumio volumio[1065]: info: Getting Spotify volume Mar 10 09:04:12 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:12 volumio volumio[1065]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Mar 10 09:04:12 volumio volumio[1065]: (node:1065) 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: 29) Mar 10 09:04:12 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 10 09:04:12 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState Mar 10 09:04:12 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:04:12 volumio volumio[1065]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 10 09:04:13 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:13 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:04:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 88. Mar 10 09:04:13 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:04:13 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:04:13 volumio go-librespot[2513]: go-librespot daemon starting... Mar 10 09:04:13 volumio go-librespot[2513]: time="2025-03-10T09:04:13+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:04:13 volumio go-librespot[2513]: time="2025-03-10T09:04:13+11:00" level=debug msg="app state loaded" Mar 10 09:04:13 volumio go-librespot[2513]: time="2025-03-10T09:04:13+11:00" level=debug msg="stored credentials not found" Mar 10 09:04:13 volumio go-librespot[2513]: time="2025-03-10T09:04:13+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:04:13 volumio go-librespot[2513]: time="2025-03-10T09:04:13+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:04:13 volumio go-librespot[2513]: time="2025-03-10T09:04:13+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:04:13 volumio go-librespot[2513]: time="2025-03-10T09:04:13+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:04:13 volumio go-librespot[2513]: time="2025-03-10T09:04:13+11:00" level=info msg="zeroconf server listening on port 35401" Mar 10 09:04:13 volumio volumio[1065]: info: Executing endpoint metavolumio Mar 10 09:04:13 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 10 09:04:13 volumio go-librespot[2513]: time="2025-03-10T09:04:13+11:00" level=debug msg="obtained new client token: AACrTYOID2703UVekTIj8MByq4cfbKZDqwGTuTLg6RCVRM5dduCSoJEKt+ehvtwYpSprgknFs5XQbHNthZR8caGum62vjG2QBlgWaaw8ty2vHDgco7UE/Y3gp8dOzFRvJwtj5hIjtBBx+/nhcRN2txgCaYrLbZuNN43/W5JOO1Vm2ctL1NgGOYYK1tsqixnL+3UJV4YKS99bBknHVdHQITNE7Ht0D7vXVoE7cuAuVAgOXEXYeEicRboNk03o" Mar 10 09:04:14 volumio go-librespot[2513]: time="2025-03-10T09:04:14+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:04:14 volumio go-librespot[2513]: time="2025-03-10T09:04:14+11:00" level=debug msg="completed keyexchange" Mar 10 09:04:14 volumio go-librespot[2513]: time="2025-03-10T09:04:14+11:00" level=debug msg="completed challenge" Mar 10 09:04:14 volumio go-librespot[2513]: time="2025-03-10T09:04:14+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:04:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:04:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:04:16 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:16 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:04:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 89. Mar 10 09:04:17 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:04:17 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:04:17 volumio go-librespot[2522]: go-librespot daemon starting... Mar 10 09:04:17 volumio go-librespot[2522]: time="2025-03-10T09:04:17+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:04:17 volumio go-librespot[2522]: time="2025-03-10T09:04:17+11:00" level=debug msg="app state loaded" Mar 10 09:04:17 volumio go-librespot[2522]: time="2025-03-10T09:04:17+11:00" level=debug msg="stored credentials not found" Mar 10 09:04:17 volumio go-librespot[2522]: time="2025-03-10T09:04:17+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:04:17 volumio go-librespot[2522]: time="2025-03-10T09:04:17+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:04:17 volumio go-librespot[2522]: time="2025-03-10T09:04:17+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:04:17 volumio go-librespot[2522]: time="2025-03-10T09:04:17+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:04:17 volumio go-librespot[2522]: time="2025-03-10T09:04:17+11:00" level=info msg="zeroconf server listening on port 41907" Mar 10 09:04:18 volumio go-librespot[2522]: time="2025-03-10T09:04:18+11:00" level=debug msg="obtained new client token: AACg5Q1ZO+3qsaYPmyykrc4FSnv1rmTU2rbqV8p1N4IOuBhei+wKLlyU1qd4BusTEnHRrMzB2dNB5Kunt2ua5ctUywg7l9ZvPI7t27fXwkV2yip9F6RkXJ5kY0fsPHdBvALUd8P2QVnJZJhVkl+/OZ4fGYAgSe6Dnz/UZkMr9hs4RudX3FHKA1imygyNgFB/ifECAFA9Vt0bbc8a0p1W8yOa+KHcLm0llNYMyuuKLI7lhvG+TDc9Eg7fAg==" Mar 10 09:04:18 volumio go-librespot[2522]: time="2025-03-10T09:04:18+11:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Mar 10 09:04:18 volumio go-librespot[2522]: time="2025-03-10T09:04:18+11:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 10 09:04:18 volumio go-librespot[2522]: time="2025-03-10T09:04:18+11:00" level=debug msg="completed keyexchange" Mar 10 09:04:18 volumio go-librespot[2522]: time="2025-03-10T09:04:18+11:00" level=debug msg="completed challenge" Mar 10 09:04:18 volumio go-librespot[2522]: time="2025-03-10T09:04:18+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:04:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:04:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:04:19 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:19 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:19 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 10 09:04:19 volumio volumio[1065]: info: Preload queue cleared Mar 10 09:04:21 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:04:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 90. Mar 10 09:04:21 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:04:21 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:04:21 volumio go-librespot[2530]: go-librespot daemon starting... Mar 10 09:04:21 volumio go-librespot[2530]: time="2025-03-10T09:04:21+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:04:21 volumio go-librespot[2530]: time="2025-03-10T09:04:21+11:00" level=debug msg="app state loaded" Mar 10 09:04:21 volumio go-librespot[2530]: time="2025-03-10T09:04:21+11:00" level=debug msg="stored credentials not found" Mar 10 09:04:21 volumio go-librespot[2530]: time="2025-03-10T09:04:21+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:04:21 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 10 09:04:22 volumio volumio[1065]: info: Preload queue cleared Mar 10 09:04:22 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=debug msg="new websocket client" Mar 10 09:04:22 volumio volumio[1065]: info: Connection to go-librespot Websocket established Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=info msg="zeroconf server listening on port 44183" Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=debug msg="obtained new client token: AAAsNlQ446JExTDtKZs3c665lp66pn+auoabamxd58TlCuV4sm2TPxWAo2aFDYDqmEdF9XVxQT5ZyDW53TRoujbSW8Ht5TMhd0AH41I0pwOTkBieX9la/B6c1Pfyuu/kpzbGNx+k4egmuJL7zTIHY6z8J7u8UWSV5PscGKvXmcpZ8Ojy06xwKk4DYDXOShj3cIVkQDT8wgN4wA8x/i+Z3BQYCC0RT2cMQ2BOR6jOiBIW/apTmiVDYOt2TQ==" Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=debug msg="completed keyexchange" Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=debug msg="completed challenge" Mar 10 09:04:22 volumio go-librespot[2530]: time="2025-03-10T09:04:22+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:04:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:04:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:04:22 volumio volumio[1065]: info: Connection to go-librespot Websocket closed Mar 10 09:04:23 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 10 09:04:24 volumio volumio[1065]: info: Preload queue cleared Mar 10 09:04:25 volumio volumio[1065]: info: Getting Spotify volume Mar 10 09:04:25 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:25 volumio volumio[1065]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Mar 10 09:04:25 volumio volumio[1065]: (node:1065) 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: 30) Mar 10 09:04:25 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 10 09:04:25 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState Mar 10 09:04:25 volumio volumio[1065]: info: CorePlayQueue::getTrack 0 Mar 10 09:04:25 volumio volumio[1065]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 10 09:04:25 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:25 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:25 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:04:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 91. Mar 10 09:04:25 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:04:26 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:04:26 volumio go-librespot[2539]: go-librespot daemon starting... Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=debug msg="app state loaded" Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=debug msg="stored credentials not found" Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=info msg="zeroconf server listening on port 42553" Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=debug msg="obtained new client token: AABhk8hgOiCsw4Dv3UQbJ37FNPVjLP04vB5fZKTjt7ZhreyxernjVTxhkgS+w+vJ04/heleCHtdY+gxCrIshJ0N4Y8842TmT79SxjvLdZ+WvyoXgc7ETXucWAju4qHjAjBT+miot2R7Wz+05AIM08swqivKISZqSoVL0hx3+xf2LxGgDETQi0WCIiQPQsW8fj4AQbSp8+xdjTZ/kQf8oy8C3FnWdWSpnmfwUilSN6ODFZ16FpOOqgR+Bfl2q" Mar 10 09:04:26 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=debug msg="completed keyexchange" Mar 10 09:04:26 volumio go-librespot[2539]: time="2025-03-10T09:04:26+11:00" level=debug msg="completed challenge" Mar 10 09:04:26 volumio volumio[1065]: info: Preload queue cleared Mar 10 09:04:27 volumio go-librespot[2539]: time="2025-03-10T09:04:27+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:04:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:04:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:04:28 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 10 09:04:28 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:28 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:30 volumio volumio[1065]: info: Preload queue cleared Mar 10 09:04:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:04:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 92. Mar 10 09:04:30 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:04:30 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:04:30 volumio go-librespot[2585]: go-librespot daemon starting... Mar 10 09:04:30 volumio go-librespot[2585]: time="2025-03-10T09:04:30+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:04:30 volumio go-librespot[2585]: time="2025-03-10T09:04:30+11:00" level=debug msg="app state loaded" Mar 10 09:04:30 volumio go-librespot[2585]: time="2025-03-10T09:04:30+11:00" level=debug msg="stored credentials not found" Mar 10 09:04:30 volumio go-librespot[2585]: time="2025-03-10T09:04:30+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:04:30 volumio go-librespot[2585]: time="2025-03-10T09:04:30+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:04:30 volumio go-librespot[2585]: time="2025-03-10T09:04:30+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:04:30 volumio go-librespot[2585]: time="2025-03-10T09:04:30+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:04:30 volumio go-librespot[2585]: time="2025-03-10T09:04:30+11:00" level=info msg="zeroconf server listening on port 38213" Mar 10 09:04:30 volumio go-librespot[2585]: time="2025-03-10T09:04:30+11:00" level=debug msg="obtained new client token: AABskX3RSpN1Qr79AA9lOJ7oZ6D54exppQmVrVlSeMagvwE4sA/4BOuYfKV2g9doCueiizomEzLR5YDIatQGUpQKwWZlq5/rscmKuaR56mtyCVvMXeVCS9haQZmxJKbvj/et7F4nMr85CHKjTP+GY2/dV1TtX23dshZ9c52jeZqaQnH8LuVh7nTPnTwSlpXtu5KdCRwRInoUPmZuZSPHmDTSqqJqKnTUeWPEA7rTHwaea91Ei044JPy+2b8s" Mar 10 09:04:31 volumio go-librespot[2585]: time="2025-03-10T09:04:31+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:04:31 volumio go-librespot[2585]: time="2025-03-10T09:04:31+11:00" level=debug msg="completed keyexchange" Mar 10 09:04:31 volumio go-librespot[2585]: time="2025-03-10T09:04:31+11:00" level=debug msg="completed challenge" Mar 10 09:04:31 volumio go-librespot[2585]: time="2025-03-10T09:04:31+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:04:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:04:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:04:31 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:31 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 10 09:04:34 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 10 09:04:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 93. Mar 10 09:04:34 volumio systemd[1]: Stopped go-librespot Daemon. Mar 10 09:04:34 volumio systemd[1]: Started go-librespot Daemon. Mar 10 09:04:34 volumio go-librespot[2593]: go-librespot daemon starting... Mar 10 09:04:34 volumio go-librespot[2593]: time="2025-03-10T09:04:34+11:00" level=info msg="running go-librespot 0.2.0" Mar 10 09:04:34 volumio go-librespot[2593]: time="2025-03-10T09:04:34+11:00" level=debug msg="app state loaded" Mar 10 09:04:34 volumio go-librespot[2593]: time="2025-03-10T09:04:34+11:00" level=debug msg="stored credentials not found" Mar 10 09:04:34 volumio go-librespot[2593]: time="2025-03-10T09:04:34+11:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 10 09:04:34 volumio go-librespot[2593]: time="2025-03-10T09:04:34+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 10 09:04:34 volumio go-librespot[2593]: time="2025-03-10T09:04:34+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 10 09:04:34 volumio go-librespot[2593]: time="2025-03-10T09:04:34+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 10 09:04:34 volumio go-librespot[2593]: time="2025-03-10T09:04:34+11:00" level=info msg="zeroconf server listening on port 39499" Mar 10 09:04:34 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket Mar 10 09:04:34 volumio go-librespot[2593]: time="2025-03-10T09:04:34+11:00" level=debug msg="new websocket client" Mar 10 09:04:34 volumio volumio[1065]: info: Connection to go-librespot Websocket established Mar 10 09:04:35 volumio go-librespot[2593]: time="2025-03-10T09:04:35+11:00" level=debug msg="obtained new client token: AABRMqKhV1rSAq33xP4JsECrloTtk7qp5OynSQYjIOoAgzxsZcA5meCA4QmjgtR6rDaCzNsFc/KR1tQduEP4Tk2CCid6lvuBkdEfsUmyJxVAzNyzSlz0dZJez+cHfSUuNrdYE2u1fVVrRqhOKU09PdAkcIhbKXf8CHfAaFFK5EEhcxTt6JNA5CuK0RxnIF2KNwhRqApvrSnMU+226Mqf1Y4+8+ksFGWm4LNpylR7i0Ek80Nq0+AAo65t/Q==" Mar 10 09:04:35 volumio go-librespot[2593]: time="2025-03-10T09:04:35+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 10 09:04:35 volumio go-librespot[2593]: time="2025-03-10T09:04:35+11:00" level=debug msg="completed keyexchange" Mar 10 09:04:35 volumio go-librespot[2593]: time="2025-03-10T09:04:35+11:00" level=debug msg="completed challenge" Mar 10 09:04:35 volumio go-librespot[2593]: time="2025-03-10T09:04:35+11:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 10 09:04:35 volumio volumio[1065]: info: Connection to go-librespot Websocket closed Mar 10 09:04:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 10 09:04:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 10 09:04:37 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 10 09:04:37 volumio volumio[1065]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 10 09:04:37 volumio volumio[1065]: TypeError: Cannot read property 'length' of undefined Mar 10 09:04:37 volumio volumio[1065]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Mar 10 09:04:37 volumio volumio[1065]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Mar 10 09:04:37 volumio volumio[1065]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Mar 10 09:04:37 volumio volumio[1065]: at Parser.emit (events.js:315:20) Mar 10 09:04:37 volumio volumio[1065]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Mar 10 09:04:37 volumio volumio[1065]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Mar 10 09:04:37 volumio volumio[1065]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Mar 10 09:04:37 volumio volumio[1065]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Mar 10 09:04:37 volumio volumio[1065]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Mar 10 09:04:37 volumio volumio[1065]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Mar 10 09:04:37 volumio volumio[1065]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Mar 10 09:04:37 volumio volumio[1065]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Mar 10 09:04:37 volumio volumio[1065]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Mar 10 09:04:37 volumio volumio[1065]: at IncomingMessage.emit (events.js:327:22) Mar 10 09:04:37 volumio volumio[1065]: at endReadableNT (internal/streams/readable.js:1327:12) Mar 10 09:04:37 volumio volumio[1065]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Mar 10 09:04:37 volumio volumio[1065]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 10 09:04:37 volumio sudo[2611]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-10 09:03 Mar 10 09:04:37 volumio sudo[2611]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"