-- Logs begin at Sat 2025-06-21 15:56:16 MDT, end at Sat 2025-06-21 16:22:21 MDT. -- Jun 21 16:21:02 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:05 minidsp go-librespot[3773]: time="2025-06-21T16:21:05-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jun 21 16:21:05 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:05 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: (node:791) UnhandledPromiseRejectionWarning: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: at connResetException (internal/errors.js:639:14) Jun 21 16:21:05 minidsp volumio[791]: at Socket.socketOnEnd (_http_client.js:499:23) Jun 21 16:21:05 minidsp volumio[791]: at Socket.emit (events.js:412:35) Jun 21 16:21:05 minidsp volumio[791]: at endReadableNT (internal/streams/readable.js:1333:12) Jun 21 16:21:05 minidsp volumio[791]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Jun 21 16:21:05 minidsp volumio[791]: (node:791) 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: 60) Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 21 16:21:05 minidsp volumio[791]: info: Connection to go-librespot Websocket closed Jun 21 16:21:06 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:08 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:08 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:08 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:08 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 197. Jun 21 16:21:08 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:08 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:08 minidsp go-librespot[4301]: go-librespot daemon starting... Jun 21 16:21:08 minidsp go-librespot[4301]: time="2025-06-21T16:21:08-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:08 minidsp go-librespot[4301]: time="2025-06-21T16:21:08-06:00" level=debug msg="app state loaded" Jun 21 16:21:08 minidsp go-librespot[4301]: time="2025-06-21T16:21:08-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:08 minidsp go-librespot[4301]: time="2025-06-21T16:21:08-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:09 minidsp go-librespot[4301]: time="2025-06-21T16:21:09-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:09 minidsp go-librespot[4301]: time="2025-06-21T16:21:09-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:09 minidsp go-librespot[4301]: time="2025-06-21T16:21:09-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:09 minidsp go-librespot[4301]: time="2025-06-21T16:21:09-06:00" level=info msg="zeroconf server listening on port 46719" Jun 21 16:21:09 minidsp go-librespot[4301]: time="2025-06-21T16:21:09-06:00" level=debug msg="obtained new client token: AACYN8U9jTsYPtk0zMr7aTLXFrA54lGTI98uRcZvkgnQkENZm40aMNxoQtOuT7OhEY7hR9Sjs/2T4czGDsVCb7mn5l3G0S1upqLf+GSA/XJ/DMWPtvpPomgjltz0Z/LcYnQGtVqH+OknW9w6Mu5UD95OB2mV9xWGBs9+AyPxEmTbev4WAI6ry7OsnpGplNCYrawznN2ltoVHn1k6hL1Vsc397ilghSWe5uJdWaw1tonPvZxZlYnbAfQ=" Jun 21 16:21:09 minidsp go-librespot[4301]: time="2025-06-21T16:21:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:09 minidsp go-librespot[4301]: time="2025-06-21T16:21:09-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:09 minidsp go-librespot[4301]: time="2025-06-21T16:21:09-06:00" level=debug msg="completed challenge" Jun 21 16:21:09 minidsp go-librespot[4301]: time="2025-06-21T16:21:09-06: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 " Jun 21 16:21:09 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:09 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:10 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:11 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:11 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:13 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:13 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 198. Jun 21 16:21:13 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:13 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:13 minidsp go-librespot[4310]: go-librespot daemon starting... Jun 21 16:21:13 minidsp go-librespot[4310]: time="2025-06-21T16:21:13-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:13 minidsp go-librespot[4310]: time="2025-06-21T16:21:13-06:00" level=debug msg="app state loaded" Jun 21 16:21:13 minidsp go-librespot[4310]: time="2025-06-21T16:21:13-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:13 minidsp go-librespot[4310]: time="2025-06-21T16:21:13-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:13 minidsp go-librespot[4310]: time="2025-06-21T16:21:13-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:13 minidsp go-librespot[4310]: time="2025-06-21T16:21:13-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:13 minidsp go-librespot[4310]: time="2025-06-21T16:21:13-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:13 minidsp go-librespot[4310]: time="2025-06-21T16:21:13-06:00" level=info msg="zeroconf server listening on port 44211" Jun 21 16:21:13 minidsp go-librespot[4310]: time="2025-06-21T16:21:13-06:00" level=debug msg="obtained new client token: AADb61TE5r643SLzGz/QyK1Aqc2Bu90n9muuZjpB9JNDljdYBee7B2E6+mn28JjBhJucnzi4sua/Nafy4FuAXV7hEVwfpqGSaIvmhnCooX58BHLz1JwlAvz6FaWKuTRIn9d/4Rm+R0lNAHLTz+kEtMsVOeTHsT/PbxJLDf7axKrrAlpkSp1UzjuYTrqpI7nuiN9JZwoOZJ+XYNmk0xVI4bZEOisBGCovkfbooU8XrUmohIft94zuPwE=" Jun 21 16:21:13 minidsp go-librespot[4310]: time="2025-06-21T16:21:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:14 minidsp go-librespot[4310]: time="2025-06-21T16:21:14-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:14 minidsp go-librespot[4310]: time="2025-06-21T16:21:14-06:00" level=debug msg="completed challenge" Jun 21 16:21:14 minidsp go-librespot[4310]: time="2025-06-21T16:21:14-06: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 " Jun 21 16:21:14 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:14 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:14 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:14 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:14 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:17 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:17 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 199. Jun 21 16:21:17 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:17 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:17 minidsp go-librespot[4318]: go-librespot daemon starting... Jun 21 16:21:17 minidsp go-librespot[4318]: time="2025-06-21T16:21:17-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:17 minidsp go-librespot[4318]: time="2025-06-21T16:21:17-06:00" level=debug msg="app state loaded" Jun 21 16:21:17 minidsp go-librespot[4318]: time="2025-06-21T16:21:17-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:17 minidsp go-librespot[4318]: time="2025-06-21T16:21:17-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:17 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:17 minidsp go-librespot[4318]: time="2025-06-21T16:21:17-06:00" level=debug msg="new websocket client" Jun 21 16:21:17 minidsp volumio[791]: info: Connection to go-librespot Websocket established Jun 21 16:21:17 minidsp go-librespot[4318]: time="2025-06-21T16:21:17-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:17 minidsp go-librespot[4318]: time="2025-06-21T16:21:17-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:17 minidsp go-librespot[4318]: time="2025-06-21T16:21:17-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:17 minidsp go-librespot[4318]: time="2025-06-21T16:21:17-06:00" level=info msg="zeroconf server listening on port 46761" Jun 21 16:21:18 minidsp go-librespot[4318]: time="2025-06-21T16:21:18-06:00" level=debug msg="obtained new client token: AADMEQvo0LJVq47dbrGvT4a8R8yU+uAUAPgg+k9/n0/ARt+5KsJeSj8ER3JbvDhPUBeQChGLyOQLkcvas72+F1PF9WqYen4fhyYB+XCAXNYTKJhE5/MhiCnNUSI4dU6HEnKCnlfA/YSZuTxysOph52HwfWTSTLOx82D6QH8AnNDf0Szdy1oMTMyCVAeLj0yBZsM42B8CyfF7fqSJC8ZPkhz+mUGuTmJs4LOvMYmdkDntHO1ER0at" Jun 21 16:21:18 minidsp go-librespot[4318]: time="2025-06-21T16:21:18-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:18 minidsp go-librespot[4318]: time="2025-06-21T16:21:18-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:18 minidsp go-librespot[4318]: time="2025-06-21T16:21:18-06:00" level=debug msg="completed challenge" Jun 21 16:21:18 minidsp go-librespot[4318]: time="2025-06-21T16:21:18-06: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 " Jun 21 16:21:18 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:18 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:18 minidsp volumio[791]: info: Connection to go-librespot Websocket closed Jun 21 16:21:18 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:20 minidsp volumio[791]: info: Getting Spotify volume Jun 21 16:21:20 minidsp volumio[791]: (node:791) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:20 minidsp volumio[791]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jun 21 16:21:20 minidsp volumio[791]: (node:791) 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: 61) Jun 21 16:21:20 minidsp volumio[791]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Jun 21 16:21:20 minidsp volumio[791]: info: CoreCommandRouter::volumioGetState Jun 21 16:21:20 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:21:20 minidsp volumio[791]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Jun 21 16:21:21 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:21 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:21 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:21 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 200. Jun 21 16:21:21 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:21 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:21 minidsp go-librespot[4326]: go-librespot daemon starting... Jun 21 16:21:21 minidsp go-librespot[4326]: time="2025-06-21T16:21:21-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:21 minidsp go-librespot[4326]: time="2025-06-21T16:21:21-06:00" level=debug msg="app state loaded" Jun 21 16:21:21 minidsp go-librespot[4326]: time="2025-06-21T16:21:21-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:21 minidsp go-librespot[4326]: time="2025-06-21T16:21:21-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:22 minidsp go-librespot[4326]: time="2025-06-21T16:21:22-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:22 minidsp go-librespot[4326]: time="2025-06-21T16:21:22-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:22 minidsp go-librespot[4326]: time="2025-06-21T16:21:22-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:22 minidsp go-librespot[4326]: time="2025-06-21T16:21:22-06:00" level=info msg="zeroconf server listening on port 41409" Jun 21 16:21:22 minidsp go-librespot[4326]: time="2025-06-21T16:21:22-06:00" level=debug msg="obtained new client token: AAA2Ma5bn9GlhIgbdAZeV5Ghm1WK9GIwEuWmsBzWx849DgIcTLQKycgGTxx7XWzBjnIX3S1ndGU2oTh8TmWu+U5KA3hDwpEb91hgJOL4tIh+pqfyUqSmonDRfw/l7NldXR7Yf7zDJkaGz4Tg4/vWllDyuSdSCiYQ59p2qGGKDwKmTCw2XhQ+/QqGynysYuT/zCtR2WdwyZyCoKdtB9vUfhkSdg9sjUmQNniWhObszQRYgOELo9pvM9w=" Jun 21 16:21:22 minidsp go-librespot[4326]: time="2025-06-21T16:21:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:22 minidsp go-librespot[4326]: time="2025-06-21T16:21:22-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:22 minidsp go-librespot[4326]: time="2025-06-21T16:21:22-06:00" level=debug msg="completed challenge" Jun 21 16:21:22 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:22 minidsp go-librespot[4326]: time="2025-06-21T16:21:22-06: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 " Jun 21 16:21:22 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:22 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:24 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:24 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:25 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:25 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 201. Jun 21 16:21:25 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:25 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:25 minidsp go-librespot[4374]: go-librespot daemon starting... Jun 21 16:21:25 minidsp go-librespot[4374]: time="2025-06-21T16:21:25-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:25 minidsp go-librespot[4374]: time="2025-06-21T16:21:25-06:00" level=debug msg="app state loaded" Jun 21 16:21:25 minidsp go-librespot[4374]: time="2025-06-21T16:21:25-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:25 minidsp go-librespot[4374]: time="2025-06-21T16:21:25-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:26 minidsp go-librespot[4374]: time="2025-06-21T16:21:26-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:26 minidsp go-librespot[4374]: time="2025-06-21T16:21:26-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:26 minidsp go-librespot[4374]: time="2025-06-21T16:21:26-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:26 minidsp go-librespot[4374]: time="2025-06-21T16:21:26-06:00" level=info msg="zeroconf server listening on port 45231" Jun 21 16:21:26 minidsp go-librespot[4374]: time="2025-06-21T16:21:26-06:00" level=debug msg="obtained new client token: AACzf2C4u22On+S+13zT1xRp4WOml153ljQsrglnMANu3z6e2N4dQwAcA7xEW0bw+mJ29rTVRagaaYDh1rqDljom4W8hGi0u7e6y8S/KZQ+AFolEE+ejdHuw2Qga0wdMim063bJZF4GFJGZ9tmxKy9+ubEGVFzusSXPN5PxEnsI/9+JylYfMWoGoMznJxbfdn1Ez8Wywbb6PnrNVXfVEYZdhqCVAwkn4DcLg61QtkO27Zfe5jilkP/8=" Jun 21 16:21:26 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:26 minidsp go-librespot[4374]: time="2025-06-21T16:21:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:26 minidsp go-librespot[4374]: time="2025-06-21T16:21:26-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:26 minidsp go-librespot[4374]: time="2025-06-21T16:21:26-06:00" level=debug msg="completed challenge" Jun 21 16:21:26 minidsp go-librespot[4374]: time="2025-06-21T16:21:26-06: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 " Jun 21 16:21:26 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:26 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:27 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:27 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:30 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:30 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 202. Jun 21 16:21:30 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:30 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:30 minidsp go-librespot[4382]: go-librespot daemon starting... Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=debug msg="app state loaded" Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:30 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=debug msg="new websocket client" Jun 21 16:21:30 minidsp volumio[791]: info: Connection to go-librespot Websocket established Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=info msg="zeroconf server listening on port 46245" Jun 21 16:21:30 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=debug msg="obtained new client token: AABdAVa6sZ3M0/iDR4jtxxMKf8H41qLQ2JoekYCY6/fspxnmF026qyCcWCR9B13Re6Wsqc590DBI7/pPX+WCN9F4g8OF2SonGvuSu2VS68Bb0WJ9Crp85lhlV3uxHCJj0CjbmF3+CAlqiPu1XruLfhcrNKx6zBtEsiEZrJy3743cAW0gNrA9yr/504vr4zS5uJMzH8xaNI+y7/U35OHzEcsn99rYIiisNAUMUsYpHq0yosfB4KZT3xE=" Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:30 minidsp go-librespot[4382]: time="2025-06-21T16:21:30-06:00" level=debug msg="completed challenge" Jun 21 16:21:31 minidsp go-librespot[4382]: time="2025-06-21T16:21:31-06: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 " Jun 21 16:21:31 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:31 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:31 minidsp volumio[791]: info: Connection to go-librespot Websocket closed Jun 21 16:21:33 minidsp volumio[791]: info: Getting Spotify volume Jun 21 16:21:33 minidsp volumio[791]: (node:791) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:33 minidsp volumio[791]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jun 21 16:21:33 minidsp volumio[791]: (node:791) 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: 62) Jun 21 16:21:33 minidsp volumio[791]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Jun 21 16:21:33 minidsp volumio[791]: info: CoreCommandRouter::volumioGetState Jun 21 16:21:33 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:21:33 minidsp volumio[791]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Jun 21 16:21:34 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:34 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:34 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:34 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 203. Jun 21 16:21:34 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:34 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:34 minidsp go-librespot[4392]: go-librespot daemon starting... Jun 21 16:21:34 minidsp go-librespot[4392]: time="2025-06-21T16:21:34-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:34 minidsp go-librespot[4392]: time="2025-06-21T16:21:34-06:00" level=debug msg="app state loaded" Jun 21 16:21:34 minidsp go-librespot[4392]: time="2025-06-21T16:21:34-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:34 minidsp go-librespot[4392]: time="2025-06-21T16:21:34-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:34 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:34 minidsp go-librespot[4392]: time="2025-06-21T16:21:34-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:34 minidsp go-librespot[4392]: time="2025-06-21T16:21:34-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:34 minidsp go-librespot[4392]: time="2025-06-21T16:21:34-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:34 minidsp go-librespot[4392]: time="2025-06-21T16:21:34-06:00" level=info msg="zeroconf server listening on port 46871" Jun 21 16:21:34 minidsp go-librespot[4392]: time="2025-06-21T16:21:34-06:00" level=debug msg="obtained new client token: AADlK9eDbsUz1DZBv7Sa0sofTtA9BCVhq1O9PNI8K8pn5W69AM4LSeHZvKU0dpw6lBXomuDgctEqDQEzXVFKX5m81yDYh3sc0pvMj5WpgmX+FfBO+QBDkY1W3WQROqkyYzC9vhUkbomk4FpqES1pIy9gN4BKbIDvlFEuAh3cvTi/rskPpvSZ+eszW3lowqW+M8QhQT9ply0Ww2Gv6kVVpGY0xJjHN5Apxobqv2UHMQMRRRvR8y3rLTU=" Jun 21 16:21:35 minidsp go-librespot[4392]: time="2025-06-21T16:21:35-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:35 minidsp go-librespot[4392]: time="2025-06-21T16:21:35-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:35 minidsp go-librespot[4392]: time="2025-06-21T16:21:35-06:00" level=debug msg="completed challenge" Jun 21 16:21:35 minidsp go-librespot[4392]: time="2025-06-21T16:21:35-06: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 " Jun 21 16:21:35 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:35 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:36 minidsp volumio[791]: info: Enabling MyMusic plugin raat Jun 21 16:21:36 minidsp volumio[791]: info: Enabling plugin raat Jun 21 16:21:36 minidsp volumio[791]: info: Loading plugin "raat"... Jun 21 16:21:37 minidsp volumio[791]: info: RAAT Plugin loaded Jun 21 16:21:37 minidsp volumio[791]: info: Adding restartRAATSocket REST API Endpoint Jun 21 16:21:37 minidsp volumio[791]: info: Adding restartRAATSocket REST Endpoint for plugin: music_service/raat Jun 21 16:21:37 minidsp volumio[791]: info: PLUGIN START: raat Jun 21 16:21:37 minidsp volumio[791]: info: Starting RAAT Plugin Jun 21 16:21:37 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Jun 21 16:21:37 minidsp volumio[791]: info: Additional UI Settings Added for plugin music_service/raat Jun 21 16:21:37 minidsp volumio[791]: info: Done. Jun 21 16:21:37 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:37 minidsp volumio[791]: info: RAAT Albumart path created successfully Jun 21 16:21:37 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:38 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:38 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 204. Jun 21 16:21:38 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:38 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:38 minidsp go-librespot[4404]: go-librespot daemon starting... Jun 21 16:21:38 minidsp go-librespot[4404]: time="2025-06-21T16:21:38-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:38 minidsp go-librespot[4404]: time="2025-06-21T16:21:38-06:00" level=debug msg="app state loaded" Jun 21 16:21:38 minidsp go-librespot[4404]: time="2025-06-21T16:21:38-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:38 minidsp go-librespot[4404]: time="2025-06-21T16:21:38-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:38 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:38 minidsp go-librespot[4404]: time="2025-06-21T16:21:38-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:38 minidsp go-librespot[4404]: time="2025-06-21T16:21:38-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:38 minidsp go-librespot[4404]: time="2025-06-21T16:21:38-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:38 minidsp go-librespot[4404]: time="2025-06-21T16:21:38-06:00" level=info msg="zeroconf server listening on port 43801" Jun 21 16:21:39 minidsp go-librespot[4404]: time="2025-06-21T16:21:39-06:00" level=debug msg="obtained new client token: AADlvTVODCkI6uhUafUMeOswgdB/tsgRy27rAnDGDbPthGCalpOVKw6MT1NOjN8AQ5SKGUR8SjXP7oAtt7Gh0n4DNeIx6N14phFn6NAQrjomShd6ujCSoHhhkfIyxS13SQKOKppaWgKFf98MWR+A6zuLZgeRNClmSEnNB2y5fs9XXLx+h/Hkbqk3pSVeZmE+Fv6baSBQXx7KJQzRLy2ICvw6K7IgaMW9kvCrXt9BhDcF+nDr8r96" Jun 21 16:21:39 minidsp go-librespot[4404]: time="2025-06-21T16:21:39-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:39 minidsp go-librespot[4404]: time="2025-06-21T16:21:39-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:39 minidsp go-librespot[4404]: time="2025-06-21T16:21:39-06:00" level=debug msg="completed challenge" Jun 21 16:21:39 minidsp go-librespot[4404]: time="2025-06-21T16:21:39-06: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 " Jun 21 16:21:39 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:39 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:40 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:40 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:42 minidsp volumio[791]: info: Enabling MyMusic plugin cd_controller Jun 21 16:21:42 minidsp volumio[791]: info: Enabling plugin cd_controller Jun 21 16:21:42 minidsp volumio[791]: info: Loading plugin "cd_controller"... Jun 21 16:21:42 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:42 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 205. Jun 21 16:21:42 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:42 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:42 minidsp go-librespot[4412]: go-librespot daemon starting... Jun 21 16:21:42 minidsp go-librespot[4412]: time="2025-06-21T16:21:42-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:42 minidsp go-librespot[4412]: time="2025-06-21T16:21:42-06:00" level=debug msg="app state loaded" Jun 21 16:21:42 minidsp go-librespot[4412]: time="2025-06-21T16:21:42-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:42 minidsp go-librespot[4412]: time="2025-06-21T16:21:42-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:43 minidsp volumio[791]: info: PLUGIN START: cd_controller Jun 21 16:21:43 minidsp volumio[791]: info: Preparing CD Folders Jun 21 16:21:43 minidsp volumio[791]: info: Adding CD REST API Endpoints Jun 21 16:21:43 minidsp volumio[791]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Jun 21 16:21:43 minidsp volumio[791]: info: Starting UDEV Watcher for CD Jun 21 16:21:43 minidsp volumio[791]: info: Detecting CD presence with UDEV Jun 21 16:21:43 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Jun 21 16:21:43 minidsp volumio[791]: info: Done. Jun 21 16:21:43 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:43 minidsp go-librespot[4412]: time="2025-06-21T16:21:43-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:43 minidsp go-librespot[4412]: time="2025-06-21T16:21:43-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:43 minidsp go-librespot[4412]: time="2025-06-21T16:21:43-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:43 minidsp go-librespot[4412]: time="2025-06-21T16:21:43-06:00" level=info msg="zeroconf server listening on port 45267" Jun 21 16:21:43 minidsp volumio[791]: info: Enabling MyMusic plugin tidalconnect Jun 21 16:21:43 minidsp volumio[791]: info: Enabling plugin tidalconnect Jun 21 16:21:43 minidsp volumio[791]: info: Loading plugin "tidalconnect"... Jun 21 16:21:43 minidsp go-librespot[4412]: time="2025-06-21T16:21:43-06:00" level=debug msg="obtained new client token: AAAK6T+i4wiKBNnUmNdRC+edrauRWd0rzNiEsPvo4d9bfVnyLAoiwy4QBzZSXbL8M2UZ3xrpaA0DQGMjfdGvhCpbDGd0SDRzbKhRPSBfZbxBS9t8xy/YDI1X4GbTwUlIRolhUbuuojM/QZmbsBxW8w0XJEQPzUtO4jrm19uO79djbabKxhWIwzgDjm1f54qnUMGKN1WC1lOmfaFkBW+1CPmmZN6+vLQLkpUK7LWRGMR/SZWAS/+NyBg=" Jun 21 16:21:43 minidsp go-librespot[4412]: time="2025-06-21T16:21:43-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:43 minidsp go-librespot[4412]: time="2025-06-21T16:21:43-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:43 minidsp go-librespot[4412]: time="2025-06-21T16:21:43-06:00" level=debug msg="completed challenge" Jun 21 16:21:43 minidsp go-librespot[4412]: time="2025-06-21T16:21:43-06: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 " Jun 21 16:21:43 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:43 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:43 minidsp volumio[791]: info: PLUGIN START: tidalconnect Jun 21 16:21:43 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: inputs , getVolume Jun 21 16:21:43 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: inputs , getDSP Jun 21 16:21:43 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:43 minidsp volumio[791]: info: msSurfaceDial volumioupdatevolume callback: {"vol":72,"dbVolume":-35.5,"mute":false,"disableVolumeControl":false} Jun 21 16:21:43 minidsp sudo[4422]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Jun 21 16:21:43 minidsp volumio[791]: info: CoreStateMachine::pushState Jun 21 16:21:43 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:21:43 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 21 16:21:43 minidsp sudo[4422]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 16:21:43 minidsp volumio[791]: info: CoreCommandRouter::volumioPushState Jun 21 16:21:43 minidsp volumio[791]: info: MRS: Pushing multiroomSync output update for this device Jun 21 16:21:43 minidsp volumio[791]: info: MRS: Pushing multiroomSync output Jun 21 16:21:43 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume Jun 21 16:21:43 minidsp volumio[791]: error: Cannot write to RAAT Client: TypeError: Cannot read property 'write' of undefined Jun 21 16:21:43 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: raat , updateDSP Jun 21 16:21:43 minidsp volumio[791]: info: updateDSP function in raat called! Jun 21 16:21:43 minidsp volumio[791]: info: Updating RAAT Signal Path Jun 21 16:21:43 minidsp volumio[791]: error: Cannot write to RAAT Client: TypeError: Cannot read property 'write' of undefined Jun 21 16:21:43 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:43 minidsp sudo[4422]: pam_unix(sudo:session): session closed for user root Jun 21 16:21:43 minidsp volumio[791]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Jun 21 16:21:46 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:46 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:46 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 206. Jun 21 16:21:46 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:46 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:46 minidsp go-librespot[4426]: go-librespot daemon starting... Jun 21 16:21:46 minidsp go-librespot[4426]: time="2025-06-21T16:21:46-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:46 minidsp go-librespot[4426]: time="2025-06-21T16:21:46-06:00" level=debug msg="app state loaded" Jun 21 16:21:46 minidsp go-librespot[4426]: time="2025-06-21T16:21:46-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:46 minidsp go-librespot[4426]: time="2025-06-21T16:21:46-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:46 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:46 minidsp go-librespot[4426]: time="2025-06-21T16:21:46-06:00" level=debug msg="new websocket client" Jun 21 16:21:46 minidsp volumio[791]: info: Connection to go-librespot Websocket established Jun 21 16:21:46 minidsp volumio[791]: info: TidalConnect service stoped! Jun 21 16:21:47 minidsp volumio[791]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Jun 21 16:21:47 minidsp volumio[791]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Jun 21 16:21:47 minidsp sudo[4443]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Jun 21 16:21:47 minidsp sudo[4443]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 16:21:47 minidsp systemd[1]: Started Volumio Tidal Connect Service. Jun 21 16:21:47 minidsp sudo[4443]: pam_unix(sudo:session): session closed for user root Jun 21 16:21:47 minidsp go-librespot[4426]: time="2025-06-21T16:21:47-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 21 16:21:47 minidsp go-librespot[4426]: time="2025-06-21T16:21:47-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 21 16:21:47 minidsp go-librespot[4426]: time="2025-06-21T16:21:47-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 21 16:21:47 minidsp go-librespot[4426]: time="2025-06-21T16:21:47-06:00" level=info msg="zeroconf server listening on port 42535" Jun 21 16:21:47 minidsp go-librespot[4426]: time="2025-06-21T16:21:47-06:00" level=debug msg="obtained new client token: AABsY3RZ+x7PjUqvpJ45K4ijjv7eOq8wAOwM29XpKfzUoIW9+d5ZuRqDApsXg4SFBuZ7WBqduI8MF+H1PXrTStD/DN3BjEXraYPuRuWyPZBjvh9C5Nv4lUGd+7+10oFHS2QqjKj2t4f1yi7PNanOEVs97X+OiH/ZIR+L6bwdGJXYz2KMNvJt7MF6rX45YmHqlA3ke4yh31iJsFIu21TZilXGv2ef5fOGaj62t20tM1ohZecebfWsPUw=" Jun 21 16:21:47 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 16:21:47 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 16:21:47 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 21 16:21:47 minidsp volumio[791]: info: Not Reporting Auto name since its the default one Jun 21 16:21:47 minidsp volumio[791]: info: RAAT Overriding default device vendor model Jun 21 16:21:47 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Jun 21 16:21:47 minidsp go-librespot[4426]: time="2025-06-21T16:21:47-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:47 minidsp volumio[791]: xcb_connection_has_error() returned true Jun 21 16:21:47 minidsp go-librespot[4426]: time="2025-06-21T16:21:47-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:47 minidsp go-librespot[4426]: time="2025-06-21T16:21:47-06:00" level=debug msg="completed challenge" Jun 21 16:21:47 minidsp sudo[4456]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Jun 21 16:21:47 minidsp sudo[4456]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 16:21:47 minidsp go-librespot[4426]: time="2025-06-21T16:21:47-06: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 " Jun 21 16:21:47 minidsp volumio[791]: info: Connection to go-librespot Websocket closed Jun 21 16:21:47 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:48 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:48 minidsp systemd[1]: Started RAAT DAEMON. Jun 21 16:21:48 minidsp sudo[4456]: pam_unix(sudo:session): session closed for user root Jun 21 16:21:48 minidsp volumio[791]: info: Raat Daemon started successfully Jun 21 16:21:48 minidsp volumio[791]: info: Executing endpoint tc_getconfig Jun 21 16:21:48 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Jun 21 16:21:48 minidsp vtcs[4445]: STARTING TidalConnect services, version: 1.3.0.19 Jun 21 16:21:48 minidsp volumio[791]: info: Executing endpoint restartRAATSocket Jun 21 16:21:48 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Jun 21 16:21:48 minidsp vtcs[4445]: STARTED TidalConnect services. Jun 21 16:21:48 minidsp volumio[791]: info: Executing endpoint tc_connect Jun 21 16:21:48 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Jun 21 16:21:48 minidsp volumio[791]: info: Connecting to TidalConnect Jun 21 16:21:48 minidsp volumio[791]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Jun 21 16:21:48 minidsp volumio[791]: info: CoreCommandRouter::servicePushState Jun 21 16:21:48 minidsp volumio[791]: info: CoreStateMachine::pushState Jun 21 16:21:48 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:21:48 minidsp volumio[791]: info: CoreCommandRouter::volumioPushState Jun 21 16:21:48 minidsp volumio[791]: info: MRS: Pushing multiroomSync output update for this device Jun 21 16:21:48 minidsp volumio[791]: info: MRS: Pushing multiroomSync output Jun 21 16:21:48 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:21:48 minidsp volumio[791]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Jun 21 16:21:48 minidsp volumio[791]: info: CoreCommandRouter::servicePushState Jun 21 16:21:48 minidsp volumio[791]: info: CoreStateMachine::pushState Jun 21 16:21:48 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:21:48 minidsp volumio[791]: info: CoreCommandRouter::volumioPushState Jun 21 16:21:48 minidsp volumio[791]: info: MRS: Pushing multiroomSync output update for this device Jun 21 16:21:48 minidsp volumio[791]: info: MRS: Pushing multiroomSync output Jun 21 16:21:48 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:21:48 minidsp volumio[791]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Jun 21 16:21:48 minidsp volumio[791]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Jun 21 16:21:48 minidsp volumio[791]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Jun 21 16:21:48 minidsp volumio[791]: info: CoreCommandRouter::volumioGetState Jun 21 16:21:48 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:21:49 minidsp volumio[791]: info: Getting Spotify volume Jun 21 16:21:49 minidsp volumio[791]: (node:791) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:49 minidsp volumio[791]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jun 21 16:21:49 minidsp volumio[791]: (node:791) 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: 63) Jun 21 16:21:49 minidsp volumio[791]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Jun 21 16:21:49 minidsp volumio[791]: info: CoreCommandRouter::volumioGetState Jun 21 16:21:49 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:21:50 minidsp volumio[791]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Jun 21 16:21:50 minidsp volumio[791]: info: TidalConnect service started! Jun 21 16:21:50 minidsp volumio[791]: info: Done. Jun 21 16:21:50 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:50 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:50 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:51 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:51 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 207. Jun 21 16:21:51 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:51 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:51 minidsp go-librespot[4484]: go-librespot daemon starting... Jun 21 16:21:51 minidsp go-librespot[4484]: time="2025-06-21T16:21:51-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:51 minidsp go-librespot[4484]: time="2025-06-21T16:21:51-06:00" level=debug msg="app state loaded" Jun 21 16:21:51 minidsp go-librespot[4484]: time="2025-06-21T16:21:51-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:51 minidsp go-librespot[4484]: time="2025-06-21T16:21:51-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:51 minidsp go-librespot[4484]: time="2025-06-21T16:21:51-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 21 16:21:51 minidsp go-librespot[4484]: time="2025-06-21T16:21:51-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 21 16:21:51 minidsp go-librespot[4484]: time="2025-06-21T16:21:51-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 21 16:21:51 minidsp go-librespot[4484]: time="2025-06-21T16:21:51-06:00" level=info msg="zeroconf server listening on port 34617" Jun 21 16:21:51 minidsp go-librespot[4484]: time="2025-06-21T16:21:51-06:00" level=debug msg="obtained new client token: AAAGsI3OQ1VSpvU7fZ9wuBWIcJcLwlij4WZMVC7+0nPCfv1XPdqk/jcDqdbZlLuOKB4psxoxKlicsBynl0xpK5nXE9Fq4bmyCO2ZCfq0khQPF9n0KkY9KFjMgK3IzBnj+mgHW27IXKfzTW3kW96OkvFty4XWDUuWsRpH9yEsDHWdzIAMVULbKGAy0p94mCokcPj8CqvMbtlsbF3HZ72jYINyK0sGK3dWr5KZzDwaCKzvxNivhKG/oR8=" Jun 21 16:21:51 minidsp go-librespot[4484]: time="2025-06-21T16:21:51-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:52 minidsp go-librespot[4484]: time="2025-06-21T16:21:52-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:52 minidsp go-librespot[4484]: time="2025-06-21T16:21:52-06:00" level=debug msg="completed challenge" Jun 21 16:21:52 minidsp go-librespot[4484]: time="2025-06-21T16:21:52-06: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 " Jun 21 16:21:52 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:52 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:53 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:53 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:54 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:55 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:55 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 208. Jun 21 16:21:55 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:55 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:55 minidsp go-librespot[4493]: go-librespot daemon starting... Jun 21 16:21:55 minidsp go-librespot[4493]: time="2025-06-21T16:21:55-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:55 minidsp go-librespot[4493]: time="2025-06-21T16:21:55-06:00" level=debug msg="app state loaded" Jun 21 16:21:55 minidsp go-librespot[4493]: time="2025-06-21T16:21:55-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:55 minidsp go-librespot[4493]: time="2025-06-21T16:21:55-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:55 minidsp go-librespot[4493]: time="2025-06-21T16:21:55-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:55 minidsp go-librespot[4493]: time="2025-06-21T16:21:55-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:55 minidsp go-librespot[4493]: time="2025-06-21T16:21:55-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:55 minidsp go-librespot[4493]: time="2025-06-21T16:21:55-06:00" level=info msg="zeroconf server listening on port 39747" Jun 21 16:21:55 minidsp go-librespot[4493]: time="2025-06-21T16:21:55-06:00" level=debug msg="obtained new client token: AACF/YmeYH96gWk9j+3ntFR65fyVc3J1CJYSNNV0GokRNcWNc202sLaMTCduR0gjeVjKteSatYY1LepzwTUUfzU0FYmoSeDbpWF9xHLLu1nFrvP3tw/2U0Afgqy7rOPG0HXyCpoiHe/L9QEVTkzvND3MEApQz/M720wEHgdvYYQ8ErfmTyNANAGFiE3/dZeaZYWQZ4XhuDG13WGKUbikdJ9QNDOlmat0VAifUa6VUT/4CPq+JJqcx0A=" Jun 21 16:21:56 minidsp go-librespot[4493]: time="2025-06-21T16:21:56-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:21:56 minidsp go-librespot[4493]: time="2025-06-21T16:21:56-06:00" level=debug msg="completed keyexchange" Jun 21 16:21:56 minidsp go-librespot[4493]: time="2025-06-21T16:21:56-06:00" level=debug msg="completed challenge" Jun 21 16:21:56 minidsp go-librespot[4493]: time="2025-06-21T16:21:56-06: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 " Jun 21 16:21:56 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:21:56 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:21:56 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:21:57 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:21:57 minidsp volumio[791]: info: Disabling MyMusic plugin cd_controller Jun 21 16:21:57 minidsp volumio[791]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesAudio CD Jun 21 16:21:57 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 21 16:21:57 minidsp volumio[791]: Cannot find translation for source Presets Jun 21 16:21:57 minidsp volumio[791]: Cannot find translation for source Spotify Jun 21 16:21:57 minidsp volumio[791]: info: Stopping UDEV Watcher for CD Jun 21 16:21:57 minidsp volumio[791]: info: Disabling plugin cd_controller Jun 21 16:21:57 minidsp volumio[791]: info: Done. Jun 21 16:21:57 minidsp volumio[791]: info: Disabling MyMusic plugin raat Jun 21 16:21:57 minidsp volumio[791]: info: Stopping RAAT Plugin Jun 21 16:21:57 minidsp sudo[4503]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop raat-daemon.service Jun 21 16:21:57 minidsp sudo[4503]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 16:21:57 minidsp systemd[1]: Stopping RAAT DAEMON... Jun 21 16:21:57 minidsp systemd[1]: raat-daemon.service: Main process exited, code=killed, status=15/TERM Jun 21 16:21:57 minidsp systemd[1]: raat-daemon.service: Succeeded. Jun 21 16:21:57 minidsp systemd[1]: Stopped RAAT DAEMON. Jun 21 16:21:57 minidsp volumio[791]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 21 16:21:57 minidsp sudo[4503]: pam_unix(sudo:session): session closed for user root Jun 21 16:21:57 minidsp volumio[791]: info: Raat Daemon stopped successfully Jun 21 16:21:57 minidsp volumio[791]: info: Disabling plugin raat Jun 21 16:21:57 minidsp volumio[791]: info: Done. Jun 21 16:21:57 minidsp volumio[791]: info: Disabling MyMusic plugin tidalconnect Jun 21 16:21:57 minidsp vtcs[4445]: [2025-06-21 16:21:57.955] [tisoc] [warning] [SessionManagerImpl.cpp:243] Illegal State: IDLE Jun 21 16:21:57 minidsp vtcs[4445]: [2025-06-21 16:21:57.957] [tisoc] [error] [SpkconServer.cpp:382] recv error. client fd=8 errorno=104 error=Connection reset by peer Jun 21 16:21:57 minidsp vtcs[4445]: [2025-06-21 16:21:57.957] [tisoc] [error] [SpkconServer.cpp:377] recv error. socket disconnected Jun 21 16:21:58 minidsp volumio[791]: info: Disabling plugin tidalconnect Jun 21 16:21:58 minidsp volumio[791]: info: Done. Jun 21 16:21:58 minidsp sudo[4506]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Jun 21 16:21:58 minidsp sudo[4506]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 16:21:58 minidsp systemd[1]: Stopping Volumio Tidal Connect Service... Jun 21 16:21:58 minidsp systemd[1]: vtcs.service: Main process exited, code=killed, status=15/TERM Jun 21 16:21:58 minidsp systemd[1]: vtcs.service: Succeeded. Jun 21 16:21:58 minidsp systemd[1]: Stopped Volumio Tidal Connect Service. Jun 21 16:21:58 minidsp volumio[791]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 21 16:21:58 minidsp sudo[4506]: pam_unix(sudo:session): session closed for user root Jun 21 16:21:58 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:21:59 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:21:59 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 209. Jun 21 16:21:59 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:21:59 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:21:59 minidsp go-librespot[4509]: go-librespot daemon starting... Jun 21 16:21:59 minidsp go-librespot[4509]: time="2025-06-21T16:21:59-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:21:59 minidsp go-librespot[4509]: time="2025-06-21T16:21:59-06:00" level=debug msg="app state loaded" Jun 21 16:21:59 minidsp go-librespot[4509]: time="2025-06-21T16:21:59-06:00" level=debug msg="stored credentials not found" Jun 21 16:21:59 minidsp go-librespot[4509]: time="2025-06-21T16:21:59-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:21:59 minidsp go-librespot[4509]: time="2025-06-21T16:21:59-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:21:59 minidsp go-librespot[4509]: time="2025-06-21T16:21:59-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:21:59 minidsp go-librespot[4509]: time="2025-06-21T16:21:59-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:21:59 minidsp go-librespot[4509]: time="2025-06-21T16:21:59-06:00" level=info msg="zeroconf server listening on port 41511" Jun 21 16:22:00 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:22:00 minidsp volumio[791]: info: Connection to go-librespot Websocket established Jun 21 16:22:00 minidsp go-librespot[4509]: time="2025-06-21T16:22:00-06:00" level=debug msg="new websocket client" Jun 21 16:22:00 minidsp go-librespot[4509]: time="2025-06-21T16:22:00-06:00" level=debug msg="obtained new client token: AAA9EcfPjvsXD0mYkOHW8G2tMlXS+wfe/C8BILLyEDpbBjj/Ex7AB24aMsvIlJYxgWevLHVQC6DqHU71/IabBJIazzLl/QBL1VoCmkGDgr3547XZLY7ay3g1lPiDwTcqKjzJThuWQvyJ5MSr5NlucS89Ydau+2qpAxw8J4s3FfDZSC99xmPPbJ6pY602TBKdIdYnBW39x+5F8RACa3KdfSRGEgzu4apAUBFeE6zlyoEYU4Td7YkU" Jun 21 16:22:00 minidsp go-librespot[4509]: time="2025-06-21T16:22:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:22:00 minidsp go-librespot[4509]: time="2025-06-21T16:22:00-06:00" level=debug msg="completed keyexchange" Jun 21 16:22:00 minidsp go-librespot[4509]: time="2025-06-21T16:22:00-06:00" level=debug msg="completed challenge" Jun 21 16:22:00 minidsp go-librespot[4509]: time="2025-06-21T16:22:00-06: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 " Jun 21 16:22:00 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:22:00 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:22:00 minidsp volumio[791]: info: Connection to go-librespot Websocket closed Jun 21 16:22:01 minidsp volumio[791]: info: TidalConnect service stoped! Jun 21 16:22:02 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:22:03 minidsp volumio[791]: info: Getting Spotify volume Jun 21 16:22:03 minidsp volumio[791]: (node:791) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:22:03 minidsp volumio[791]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jun 21 16:22:03 minidsp volumio[791]: (node:791) 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: 64) Jun 21 16:22:03 minidsp volumio[791]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Jun 21 16:22:03 minidsp volumio[791]: info: CoreCommandRouter::volumioGetState Jun 21 16:22:03 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:22:03 minidsp volumio[791]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Jun 21 16:22:03 minidsp volumio[791]: info: Disabling MyMusic plugin airplay_emulation Jun 21 16:22:03 minidsp volumio[791]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesShairport-Sync Jun 21 16:22:03 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 21 16:22:03 minidsp volumio[791]: Cannot find translation for source Presets Jun 21 16:22:03 minidsp volumio[791]: Cannot find translation for source Spotify Jun 21 16:22:03 minidsp volumio[791]: info: Disabling plugin airplay_emulation Jun 21 16:22:03 minidsp volumio[791]: info: Done. Jun 21 16:22:03 minidsp sudo[4520]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop shairport-sync Jun 21 16:22:03 minidsp sudo[4520]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 16:22:03 minidsp systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 21 16:22:03 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:22:03 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:22:03 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 210. Jun 21 16:22:03 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:22:03 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:22:03 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:22:03 minidsp volumio[791]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 21 16:22:03 minidsp systemd[1]: shairport-sync.service: Succeeded. Jun 21 16:22:03 minidsp systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 21 16:22:03 minidsp go-librespot[4522]: go-librespot daemon starting... Jun 21 16:22:03 minidsp sudo[4520]: pam_unix(sudo:session): session closed for user root Jun 21 16:22:03 minidsp volumio[791]: info: Shairport-Sync Stopped Jun 21 16:22:03 minidsp go-librespot[4522]: time="2025-06-21T16:22:03-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:22:03 minidsp go-librespot[4522]: time="2025-06-21T16:22:03-06:00" level=debug msg="app state loaded" Jun 21 16:22:03 minidsp go-librespot[4522]: time="2025-06-21T16:22:03-06:00" level=debug msg="stored credentials not found" Jun 21 16:22:03 minidsp go-librespot[4522]: time="2025-06-21T16:22:03-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:22:03 minidsp go-librespot[4522]: time="2025-06-21T16:22:03-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:22:03 minidsp go-librespot[4522]: time="2025-06-21T16:22:03-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:22:03 minidsp go-librespot[4522]: time="2025-06-21T16:22:03-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:22:03 minidsp go-librespot[4522]: time="2025-06-21T16:22:03-06:00" level=info msg="zeroconf server listening on port 44625" Jun 21 16:22:04 minidsp go-librespot[4522]: time="2025-06-21T16:22:04-06:00" level=debug msg="obtained new client token: AABuTw0qUhLlZqlk0HvYsmEi38eSaQWMr/e3NxhEL4fePwHNPaT1Z3dTr7bhcU444AOojSELoLbvaevW44lcllXDoY+xi4I6iWfTTPKI1kqvZScYsroj30F14FiGTdWOXZS1j7jux40Fe8LZfjhdMM4MqOJSArIWcB53fH7J13Xg/QalaxHwMER+1sPhhkIGjwv6LT4zSFX/tBRlgaVQj0WF7/n/zUH+5kzOA0dGiCf4NgYQK78C" Jun 21 16:22:04 minidsp go-librespot[4522]: time="2025-06-21T16:22:04-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:22:04 minidsp go-librespot[4522]: time="2025-06-21T16:22:04-06:00" level=debug msg="completed keyexchange" Jun 21 16:22:04 minidsp go-librespot[4522]: time="2025-06-21T16:22:04-06:00" level=debug msg="completed challenge" Jun 21 16:22:04 minidsp go-librespot[4522]: time="2025-06-21T16:22:04-06: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 " Jun 21 16:22:04 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:22:04 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:22:06 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:22:06 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:22:06 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:22:07 minidsp volumio[791]: info: Enabling MyMusic plugin airplay_emulation Jun 21 16:22:07 minidsp volumio[791]: info: Enabling plugin airplay_emulation Jun 21 16:22:07 minidsp volumio[791]: info: Loading plugin "airplay_emulation"... Jun 21 16:22:07 minidsp volumio[791]: info: Starting Shairport Sync Jun 21 16:22:07 minidsp volumio[791]: info: PLUGIN START: airplay_emulation Jun 21 16:22:07 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 16:22:07 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 21 16:22:07 minidsp volumio[791]: xcb_connection_has_error() returned true Jun 21 16:22:07 minidsp volumio[791]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 21 16:22:07 minidsp volumio[791]: xcb_connection_has_error() returned true Jun 21 16:22:07 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 16:22:07 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 21 16:22:07 minidsp volumio[791]: xcb_connection_has_error() returned true Jun 21 16:22:07 minidsp volumio[791]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 21 16:22:07 minidsp volumio[791]: xcb_connection_has_error() returned true Jun 21 16:22:07 minidsp volumio[791]: info: Done. Jun 21 16:22:07 minidsp volumio[791]: info: Starting Shairport Sync Jun 21 16:22:07 minidsp volumio[791]: info: Starting Shairport Sync Jun 21 16:22:07 minidsp sudo[4538]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 21 16:22:07 minidsp sudo[4538]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 16:22:07 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:22:07 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 211. Jun 21 16:22:07 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:22:07 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:22:07 minidsp sudo[4541]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 21 16:22:07 minidsp sudo[4541]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 16:22:07 minidsp go-librespot[4542]: go-librespot daemon starting... Jun 21 16:22:07 minidsp systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 21 16:22:07 minidsp sudo[4538]: pam_unix(sudo:session): session closed for user root Jun 21 16:22:07 minidsp go-librespot[4542]: time="2025-06-21T16:22:07-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:22:07 minidsp go-librespot[4542]: time="2025-06-21T16:22:07-06:00" level=debug msg="app state loaded" Jun 21 16:22:07 minidsp go-librespot[4542]: time="2025-06-21T16:22:07-06:00" level=debug msg="stored credentials not found" Jun 21 16:22:07 minidsp systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 21 16:22:07 minidsp go-librespot[4542]: time="2025-06-21T16:22:07-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:22:07 minidsp volumio[791]: info: Shairport-Sync Started Jun 21 16:22:07 minidsp systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jun 21 16:22:07 minidsp systemd[1]: shairport-sync.service: Succeeded. Jun 21 16:22:07 minidsp systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 21 16:22:07 minidsp volumio[791]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 21 16:22:07 minidsp volumio[791]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jun 21 16:22:07 minidsp systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 21 16:22:07 minidsp sudo[4541]: pam_unix(sudo:session): session closed for user root Jun 21 16:22:07 minidsp volumio[791]: info: Shairport-Sync Started Jun 21 16:22:08 minidsp go-librespot[4542]: time="2025-06-21T16:22:08-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:22:08 minidsp go-librespot[4542]: time="2025-06-21T16:22:08-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:22:08 minidsp go-librespot[4542]: time="2025-06-21T16:22:08-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:22:08 minidsp go-librespot[4542]: time="2025-06-21T16:22:08-06:00" level=info msg="zeroconf server listening on port 41265" Jun 21 16:22:08 minidsp go-librespot[4542]: time="2025-06-21T16:22:08-06:00" level=debug msg="obtained new client token: AABX7hKioxd8kV9I0QTkj1tyFksGByJGkap+YJQbLcL/Wr1TbyoHLnsjw9sJaKVXImIiyE5cODAmWxxhams0ut5UeG3smXS/cBBcteO2GhzUDaDujVn+JuIQEztyM5hZ2582TMLCTqaqHJO++g0L2MqKKvscSbzNf/L4QUR0mJtrIPQcEnl9H4HjNE9KfPSbUODuiZghdZUP0U0dj3BSopuETUkCFk5tE076OlRDwgHSsVTbGxUpECI=" Jun 21 16:22:08 minidsp go-librespot[4542]: time="2025-06-21T16:22:08-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:22:08 minidsp go-librespot[4542]: time="2025-06-21T16:22:08-06:00" level=debug msg="completed keyexchange" Jun 21 16:22:08 minidsp go-librespot[4542]: time="2025-06-21T16:22:08-06:00" level=debug msg="completed challenge" Jun 21 16:22:08 minidsp go-librespot[4542]: time="2025-06-21T16:22:08-06: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 " Jun 21 16:22:08 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:22:08 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:22:09 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:22:09 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:22:10 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:22:11 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:22:11 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 212. Jun 21 16:22:11 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:22:11 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:22:11 minidsp go-librespot[4555]: go-librespot daemon starting... Jun 21 16:22:11 minidsp go-librespot[4555]: time="2025-06-21T16:22:11-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:22:11 minidsp go-librespot[4555]: time="2025-06-21T16:22:11-06:00" level=debug msg="app state loaded" Jun 21 16:22:11 minidsp go-librespot[4555]: time="2025-06-21T16:22:11-06:00" level=debug msg="stored credentials not found" Jun 21 16:22:11 minidsp go-librespot[4555]: time="2025-06-21T16:22:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:22:12 minidsp go-librespot[4555]: time="2025-06-21T16:22:12-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:22:12 minidsp go-librespot[4555]: time="2025-06-21T16:22:12-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:22:12 minidsp go-librespot[4555]: time="2025-06-21T16:22:12-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:22:12 minidsp go-librespot[4555]: time="2025-06-21T16:22:12-06:00" level=info msg="zeroconf server listening on port 33799" Jun 21 16:22:12 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:22:12 minidsp go-librespot[4555]: time="2025-06-21T16:22:12-06:00" level=debug msg="new websocket client" Jun 21 16:22:12 minidsp volumio[791]: info: Connection to go-librespot Websocket established Jun 21 16:22:12 minidsp go-librespot[4555]: time="2025-06-21T16:22:12-06:00" level=debug msg="obtained new client token: AAA/XKuEYQc7lKfOfSAICNymw65UeMgoIngXyBWTh6JWBDpgdgsnpqKRfXK46txQTUg2oCu+CPBIbSGBxyPVOGHHwBLjjnQ3p79s3y0mtmnseakWql8QPN9WoxFmA0hy8Tgzec1EJ9gh3zoypWD+UeLwVmmiNMqTqXp4iGnrSAIbvH1dIABJFkxu/b27S7Y2B6palUIh9Lp72kAU0mhR+E0sEb/OGR2CoHTJTwLc+2UP2od3qX9NiRo=" Jun 21 16:22:12 minidsp go-librespot[4555]: time="2025-06-21T16:22:12-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:22:12 minidsp go-librespot[4555]: time="2025-06-21T16:22:12-06:00" level=debug msg="completed keyexchange" Jun 21 16:22:12 minidsp go-librespot[4555]: time="2025-06-21T16:22:12-06:00" level=debug msg="completed challenge" Jun 21 16:22:12 minidsp go-librespot[4555]: time="2025-06-21T16:22:12-06: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 " Jun 21 16:22:12 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:22:12 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:22:12 minidsp volumio[791]: info: Connection to go-librespot Websocket closed Jun 21 16:22:14 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:22:15 minidsp volumio[791]: info: Getting Spotify volume Jun 21 16:22:15 minidsp volumio[791]: (node:791) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:22:15 minidsp volumio[791]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jun 21 16:22:15 minidsp volumio[791]: (node:791) 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: 65) Jun 21 16:22:15 minidsp volumio[791]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Jun 21 16:22:15 minidsp volumio[791]: info: CoreCommandRouter::volumioGetState Jun 21 16:22:15 minidsp volumio[791]: info: CorePlayQueue::getTrack 339 Jun 21 16:22:15 minidsp volumio[791]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Jun 21 16:22:15 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:22:15 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:22:15 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:22:15 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 213. Jun 21 16:22:15 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:22:15 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:22:15 minidsp volumio[791]: info: Disabling MyMusic plugin upnp Jun 21 16:22:15 minidsp go-librespot[4563]: go-librespot daemon starting... Jun 21 16:22:15 minidsp go-librespot[4563]: time="2025-06-21T16:22:15-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:22:15 minidsp go-librespot[4563]: time="2025-06-21T16:22:15-06:00" level=debug msg="app state loaded" Jun 21 16:22:15 minidsp go-librespot[4563]: time="2025-06-21T16:22:15-06:00" level=debug msg="stored credentials not found" Jun 21 16:22:15 minidsp go-librespot[4563]: time="2025-06-21T16:22:15-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:22:15 minidsp sudo[4571]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Jun 21 16:22:15 minidsp sudo[4571]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 16:22:15 minidsp systemd[1]: Stopping UPnP Renderer front-end to MPD... Jun 21 16:22:15 minidsp volumio[791]: error: Upnp client error: Error: This socket has been ended by the other party Jun 21 16:22:15 minidsp volumio[791]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 21 16:22:16 minidsp go-librespot[4563]: time="2025-06-21T16:22:16-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:22:16 minidsp go-librespot[4563]: time="2025-06-21T16:22:16-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:22:16 minidsp go-librespot[4563]: time="2025-06-21T16:22:16-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:22:16 minidsp go-librespot[4563]: time="2025-06-21T16:22:16-06:00" level=info msg="zeroconf server listening on port 39861" Jun 21 16:22:16 minidsp go-librespot[4563]: time="2025-06-21T16:22:16-06:00" level=debug msg="obtained new client token: AABPjSacZ/LIBQX+9gbaCsE9XGXSOnX+h63BgIQKDnM2olDAHGHZGpABOYfEKvs3BbnnjTweGnvDPp0q3+W+TLQlseNAwISxp+RSW4gZI5z6El4p2IkXM0EW5XOU9i56u9TNbEG+hbtjnqOSujR8WXKL+IrK/lktyRmG6S5xyLjUGHAtnXmxCZCYcAj4n6M3gE0xJQcxSXZfwiv6gjmz930/MCMsrBMaglsmJ/ddxyyUc4Cw6HJskXY=" Jun 21 16:22:16 minidsp go-librespot[4563]: time="2025-06-21T16:22:16-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 21 16:22:16 minidsp go-librespot[4563]: time="2025-06-21T16:22:16-06:00" level=debug msg="completed keyexchange" Jun 21 16:22:16 minidsp go-librespot[4563]: time="2025-06-21T16:22:16-06:00" level=debug msg="completed challenge" Jun 21 16:22:16 minidsp go-librespot[4563]: time="2025-06-21T16:22:16-06: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 " Jun 21 16:22:16 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:22:16 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:22:18 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 21 16:22:18 minidsp volumio[791]: info: Initializing connection to go-librespot Websocket Jun 21 16:22:18 minidsp volumio[791]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 16:22:20 minidsp systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 16:22:20 minidsp systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 214. Jun 21 16:22:20 minidsp systemd[1]: Stopped go-librespot Daemon. Jun 21 16:22:20 minidsp systemd[1]: Started go-librespot Daemon. Jun 21 16:22:20 minidsp go-librespot[4574]: go-librespot daemon starting... Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=info msg="running go-librespot 0.2.0" Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=debug msg="app state loaded" Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=debug msg="stored credentials not found" Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=info msg="zeroconf server listening on port 46047" Jun 21 16:22:20 minidsp volumio[791]: info: Enabling MyMusic plugin upnp Jun 21 16:22:20 minidsp volumio[791]: info: Enabling plugin upnp Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=debug msg="obtained new client token: AAB1QlHYlWQW4xWvKKtLVpWu4oeLW8IFCJ8uoveFy6B3dFdcNl3WTgLen91onrfGepSmvXmEfp63haMlepWf8+X/iO6psbxv27ywja2yu8GLahNFEqfzV7uGnGSqQc2kQ2pn/cZLHdG90X5lOTf6SBYP5dGbHBuk3UWbQC53fJ9t4GcLjS/rBD5iyMzInvoY2JUDjC8HDoZUPyfq1xB5Z+MtibckSCYiAhy9pJirxpkISHGluZRco6k=" Jun 21 16:22:20 minidsp volumio[791]: info: Loading plugin "upnp"... Jun 21 16:22:20 minidsp volumio[791]: info: [1750544540751] Starting Upmpd Daemon Jun 21 16:22:20 minidsp volumio[791]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 21 16:22:20 minidsp volumio[791]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 21 16:22:20 minidsp volumio[791]: Error: listen EADDRINUSE: address already in use :::6599 Jun 21 16:22:20 minidsp volumio[791]: at Server.setupListenHandle [as _listen2] (net.js:1331:16) Jun 21 16:22:20 minidsp volumio[791]: at listenInCluster (net.js:1379:12) Jun 21 16:22:20 minidsp volumio[791]: at Server.listen (net.js:1465:7) Jun 21 16:22:20 minidsp volumio[791]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Jun 21 16:22:20 minidsp volumio[791]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Jun 21 16:22:20 minidsp volumio[791]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Jun 21 16:22:20 minidsp volumio[791]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jun 21 16:22:20 minidsp volumio[791]: at processTicksAndRejections (internal/process/task_queues.js:77:11) { Jun 21 16:22:20 minidsp volumio[791]: code: 'EADDRINUSE', Jun 21 16:22:20 minidsp volumio[791]: errno: -98, Jun 21 16:22:20 minidsp volumio[791]: syscall: 'listen', Jun 21 16:22:20 minidsp volumio[791]: address: '::', Jun 21 16:22:20 minidsp volumio[791]: port: 6599 Jun 21 16:22:20 minidsp volumio[791]: } Jun 21 16:22:20 minidsp volumio[791]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Jun 21 16:22:20 minidsp go-librespot[4574]: time="2025-06-21T16:22:20-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 21 16:22:21 minidsp go-librespot[4574]: time="2025-06-21T16:22:21-06:00" level=debug msg="completed keyexchange" Jun 21 16:22:21 minidsp go-librespot[4574]: time="2025-06-21T16:22:21-06:00" level=debug msg="completed challenge" Jun 21 16:22:21 minidsp go-librespot[4574]: time="2025-06-21T16:22:21-06: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 " Jun 21 16:22:21 minidsp systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 16:22:21 minidsp systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 16:22:21 minidsp sudo[4591]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-21 16:21 Jun 21 16:22:21 minidsp sudo[4591]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="17fcb754ddd6bd152b01008c46cc4ba1ca48bf35" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="281cefcd7a302aa7cfba569185cf7aae19b8c376" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="minidspshd" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 22 Mar 2024 03:13:25 PM CET" VOLUMIO_VERSION="3.608" VOLUMIO_HARDWARE="nanopineo3" VOLUMIO_DEVICENAME="Nanopi Neo3" VOLUMIO_VENDOR="miniDSP" VOLUMIO_MODEL="SHD" VOLUMIO_VENDOR_MODEL="miniDSP SHD" VOLUMIO_HASH="18533ba33f8f92d7e7e459bb30f70beb"