-- Logs begin at Mon 2025-02-24 17:24:08 CET, end at Mon 2025-02-24 19:21:40 CET. -- Feb 24 19:20:00 minidsp-shd volumio[635]: info: Getting Spotify volume Feb 24 19:20:00 minidsp-shd volumio[635]: (node:635) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:00 minidsp-shd volumio[635]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 19:20:00 minidsp-shd volumio[635]: (node:635) 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: 744) Feb 24 19:20:00 minidsp-shd volumio[635]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Feb 24 19:20:00 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:20:00 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:01 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:01 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:01 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:01 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2242. Feb 24 19:20:01 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:01 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:02 minidsp-shd go-librespot[29878]: Librespot-go daemon starting... Feb 24 19:20:02 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:02+01:00" level=info msg="generated new device id: dcd7a9ce49a39daff0fab8a8f2d76992b994a09e" Feb 24 19:20:02 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:02+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:02 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:02+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 19:20:02 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:02+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 19:20:02 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:02+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 19:20:02 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:02+01:00" level=debug msg="zeroconf server listening on port 46635" Feb 24 19:20:02 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:02+01:00" level=debug msg="obtained new client token: AABN5NFKxBllS9P7HJTmzG54mw5Gv5AjL5eNGV0d9hvi+5lbXWJxcYljgoYrO0yuhW/nzoqEQQcrlqB+N308inJ4QonMbcQWOLqzE1dqkbgwC8LM/U1ykkO1Bu1R1G4LcWCYthS9kZmMPz5Hxk0jcHj/QMa00XnBJuT0d+f+A9r6Xsqrp06T0Z/w1JZJOoI3bc+uSEuRgBobW6wBJ0XY55AKoX2V+044Yxw9XK2qKWqW2GxKmugRH7VmZWDgLg==" Feb 24 19:20:02 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:02+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:02 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:02+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:03 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:03+01:00" level=debug msg="completed challenge" Feb 24 19:20:03 minidsp-shd go-librespot[29878]: time="2025-02-24T19:20:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:03 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:03 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:04 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:04 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2243. Feb 24 19:20:06 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:06 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:06 minidsp-shd go-librespot[29894]: Librespot-go daemon starting... Feb 24 19:20:06 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:06+01:00" level=info msg="generated new device id: 9f35c11487e115f5fd3ecdc51f25d1d9c3825300" Feb 24 19:20:06 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:06+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:06 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:06+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:20:06 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:06+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:20:06 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:06+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:20:06 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:06+01:00" level=debug msg="zeroconf server listening on port 34305" Feb 24 19:20:06 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:06+01:00" level=debug msg="obtained new client token: AADE+URhVp6VmeeRqEoZIwc+l+cvhxD4HgfOL4laNy/y4KhUCT6H6GWPXyaR5Cc2t9CUsQa8LVPPwiR0n/UsDwJS/Wkf+oTZqah84Llj2XmM80BxtHepNGRUZsrycynVr/WeXrMLjTkALBGN+ZOg4hXVYxdZMQz7oi+ZZ5GnPp6dD2dxIgJtT0TA1musJWJJaTJJfGejEJbLSkpaLXXrqZj+FwFKdwBNc+CdPS3MVzObzWuUnfkIHygbSrMSnQ==" Feb 24 19:20:06 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:06+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:06 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:06+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:07 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:07+01:00" level=debug msg="completed challenge" Feb 24 19:20:07 minidsp-shd go-librespot[29894]: time="2025-02-24T19:20:07+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:07 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:07 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:10 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:10 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2244. Feb 24 19:20:10 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:10 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:10 minidsp-shd go-librespot[29912]: Librespot-go daemon starting... Feb 24 19:20:10 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:10+01:00" level=info msg="generated new device id: 06c82bd5ccc7321bab2634f0b294ce88b0449139" Feb 24 19:20:10 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:10+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:10 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:10 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:10+01:00" level=debug msg="new websocket client" Feb 24 19:20:10 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket established Feb 24 19:20:10 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:10+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 19:20:10 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:10+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 19:20:10 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:10+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 19:20:10 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:10+01:00" level=debug msg="zeroconf server listening on port 40645" Feb 24 19:20:11 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:11+01:00" level=debug msg="obtained new client token: AAAEmihLnfNWTrpEA2R+t6GaltU0L2FKpXJnJZQtdkRzRtXkGiFShsH226ku8gYWxzI0QwOuOgy/M2M1RolZu9IRvsnTitB8n+c3Are0GxIlQcFX6yukO/HCa/c/gc3DVsHwcmM5U3zqhLL1NcfAacicdty9eCC2YHjpPKWj7SWrniQ5Lm6ENLvad4PQcu7hYERvsUUT7xk3jNs+t/dYruEX5MTt/Q6YT7NjCYjOovGcoH4zTjbzTzLVY6kGow==" Feb 24 19:20:11 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:11+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:11 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:11+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:11 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:11+01:00" level=debug msg="completed challenge" Feb 24 19:20:11 minidsp-shd go-librespot[29912]: time="2025-02-24T19:20:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:11 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket closed Feb 24 19:20:13 minidsp-shd volumio[635]: info: Getting Spotify volume Feb 24 19:20:13 minidsp-shd volumio[635]: (node:635) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:13 minidsp-shd volumio[635]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 19:20:13 minidsp-shd volumio[635]: (node:635) 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: 745) Feb 24 19:20:13 minidsp-shd volumio[635]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Feb 24 19:20:13 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:20:13 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2245. Feb 24 19:20:14 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:14 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:14 minidsp-shd go-librespot[29928]: Librespot-go daemon starting... Feb 24 19:20:14 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:14 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:14 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:14+01:00" level=info msg="generated new device id: 18616ed0658249672d6dfe9b5d2a6c5b8df840d8" Feb 24 19:20:14 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:14+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:15 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:20:15 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:15+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:20:15 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:15+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:20:15 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:15+01:00" level=debug msg="zeroconf server listening on port 35423" Feb 24 19:20:15 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:15+01:00" level=debug msg="obtained new client token: AAAhrQyGmV4+FhvCwWfD0v0t4NXqR+1+wHrMhhmxoEd1dDD3E29EXmyocXQE7ypzooZvzgkNsZGrPy/VVitUCI5XVCidTQzfq15ZHGorOVZq8pWJanERWchEPQPMFbWUfAYSM///okunJ1C8qZSq0SHQ79ukzkY8s2ZPt1c9305PrJCbLITn/3HwWiRBDzIqvjLMt7qln+Myr1WsivYozmK5O4tk5X2mHF2OuVIkIrorkKcSrvNqFMLsq6b+Wg==" Feb 24 19:20:15 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:15+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:15 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:15+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:16 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:16+01:00" level=debug msg="completed challenge" Feb 24 19:20:16 minidsp-shd go-librespot[29928]: time="2025-02-24T19:20:16+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:16 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:16 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:17 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:17 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:18 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 0 Feb 24 19:20:18 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 1 Feb 24 19:20:18 minidsp-shd volumio[635]: info: Prefetching next song Feb 24 19:20:18 minidsp-shd volumio[635]: info: [1740421218129] ControllerQobuz::prefetch Feb 24 19:20:18 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/46201113" Feb 24 19:20:18 minidsp-shd volumio[635]: STREAMING PROXY: Handling url /?data=qobuz://song/46201113 Feb 24 19:20:18 minidsp-shd volumio[635]: info: Executing endpoint getStreamUrlqobuz Feb 24 19:20:18 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Feb 24 19:20:18 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri Feb 24 19:20:18 minidsp-shd volumio[635]: info: getStreamUrl took 501 milliseconds Feb 24 19:20:18 minidsp-shd volumio[635]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=3504051&eid=46201113&fmt=6&profile=raw&app_id=539451548&cid=2505592&etsp=1740424818&hmac=1Z-3bldGOQciZafNEJfx6CYTsPY Feb 24 19:20:18 minidsp-shd volumio[635]: info: handleBrowseUri took 470 milliseconds Feb 24 19:20:19 minidsp-shd volumio[635]: info: Preload queue cleared Feb 24 19:20:19 minidsp-shd volumio[635]: info: Preloading song: qobuz://song/17587549 Feb 24 19:20:19 minidsp-shd volumio[635]: info: Preloading song: qobuz://song/17587550 Feb 24 19:20:19 minidsp-shd volumio[635]: info: Preloading song: qobuz://song/17587551 Feb 24 19:20:19 minidsp-shd volumio[635]: info: Preloading song: qobuz://song/17587552 Feb 24 19:20:19 minidsp-shd volumio[635]: STREAMING PROXY: Response: 200, length: 27366375 Feb 24 19:20:19 minidsp-shd volumio[635]: STREAMING PROXY: Client dropped request, destroying Feb 24 19:20:19 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/46201113" Feb 24 19:20:19 minidsp-shd volumio[635]: info: Exploding uri qobuz://song/17587549 in service qobuz Feb 24 19:20:19 minidsp-shd volumio[635]: STREAMING PROXY: Handling url /?data=qobuz://song/46201113 Feb 24 19:20:19 minidsp-shd volumio[635]: info: Feb 24 19:20:19 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:19 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:19 minidsp-shd volumio[635]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/46201113" took 20 milliseconds Feb 24 19:20:19 minidsp-shd volumio[635]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 24 19:20:19 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand consume 1 Feb 24 19:20:19 minidsp-shd volumio[635]: info: Feb 24 19:20:19 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:19 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:19 minidsp-shd volumio[635]: info: Feb 24 19:20:19 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:19 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:19 minidsp-shd volumio[635]: info: ------------------------------ 33ms Feb 24 19:20:19 minidsp-shd volumio[635]: info: sendMpdCommand consume 1 took 24 milliseconds Feb 24 19:20:19 minidsp-shd volumio[635]: info: ------------------------------ 20ms Feb 24 19:20:19 minidsp-shd volumio[635]: info: ------------------------------ 16ms Feb 24 19:20:19 minidsp-shd volumio[635]: info: Exploding uri qobuz://song/17587550 in service qobuz Feb 24 19:20:19 minidsp-shd volumio[635]: info: Executing endpoint getStreamUrlqobuz Feb 24 19:20:19 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Feb 24 19:20:19 minidsp-shd volumio[635]: info: Exploding uri qobuz://song/17587551 in service qobuz Feb 24 19:20:19 minidsp-shd volumio[635]: info: Exploding uri qobuz://song/17587552 in service qobuz Feb 24 19:20:19 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:19 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2246. Feb 24 19:20:19 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:19 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:19 minidsp-shd go-librespot[29948]: Librespot-go daemon starting... Feb 24 19:20:19 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:19+01:00" level=info msg="generated new device id: 91aced1ef25adb6aa1ceec1a90936c5ebe073999" Feb 24 19:20:19 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:19+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:19 minidsp-shd volumio[635]: info: Executing endpoint getSimilarAlbums Feb 24 19:20:19 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Feb 24 19:20:19 minidsp-shd volumio[635]: info: Executing endpoint getSimilarAlbums Feb 24 19:20:19 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Feb 24 19:20:19 minidsp-shd volumio[635]: info: Executing endpoint getSimilarAlbums Feb 24 19:20:19 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Feb 24 19:20:19 minidsp-shd volumio[635]: info: explodeUri took 496 milliseconds Feb 24 19:20:19 minidsp-shd volumio[635]: info: Executing endpoint metavolumio Feb 24 19:20:19 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 24 19:20:19 minidsp-shd volumio[635]: info: Executing endpoint metavolumio Feb 24 19:20:19 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 24 19:20:19 minidsp-shd volumio[635]: info: Executing endpoint metavolumio Feb 24 19:20:19 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 24 19:20:19 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 19:20:19 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:19+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 19:20:19 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:19+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 19:20:19 minidsp-shd volumio[635]: info: getStreamUrl took 562 milliseconds Feb 24 19:20:19 minidsp-shd volumio[635]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=3504051&eid=46201113&fmt=6&profile=raw&app_id=539451548&cid=2505592&etsp=1740424819&hmac=VVwVweyX3THe_Ji8E4d3JOrc2Mc Feb 24 19:20:19 minidsp-shd volumio[635]: info: explodeUri took 642 milliseconds Feb 24 19:20:19 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:19+01:00" level=debug msg="zeroconf server listening on port 40873" Feb 24 19:20:19 minidsp-shd volumio[635]: info: explodeUri took 589 milliseconds Feb 24 19:20:19 minidsp-shd volumio[635]: info: explodeUri took 559 milliseconds Feb 24 19:20:19 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:19+01:00" level=debug msg="obtained new client token: AAAt73FxZY/a1QSb7/qOUHiKlkAIHvNYdW5Rm9HkhA0MIj2D3+JAqdNuwDxUnvUp7u5RR00E2xEHUGqV8LD7YDCbReZ5gNXajl3iJd5LE9JzfLN73HJuOZ6dbwa2yGoyiqxtwSvEdf0/HKYtBu694P5vPFpDIbrGTSeW6ZGvxjFB54rGqPh4tA04z6hXaGlFe2V/eKISV9FbjviMTdWoeT54xogFu02Z41hjODMxW1aTNUwTfJWZKPc1zh8aSA==" Feb 24 19:20:19 minidsp-shd volumio[635]: STREAMING PROXY: Response: 200, length: 27366375 Feb 24 19:20:19 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:19+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:20 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:20+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:20 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:20 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:20+01:00" level=debug msg="new websocket client" Feb 24 19:20:20 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket established Feb 24 19:20:21 minidsp-shd volumio[635]: info: Executing endpoint metavolumio Feb 24 19:20:21 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 24 19:20:21 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:21+01:00" level=debug msg="completed challenge" Feb 24 19:20:21 minidsp-shd go-librespot[29948]: time="2025-02-24T19:20:21+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:21 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:21 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:21 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket closed Feb 24 19:20:22 minidsp-shd volumio[635]: error: Failed request for metavolumio API Feb 24 19:20:22 minidsp-shd volumio[635]: info: Executing endpoint metavolumio Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 24 19:20:22 minidsp-shd volumio[635]: info: Executing endpoint metavolumio Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::startPlaybackTimer Feb 24 19:20:22 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 1 Feb 24 19:20:22 minidsp-shd volumio[635]: info: Feb 24 19:20:22 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:22 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:22 minidsp-shd volumio[635]: info: Feb 24 19:20:22 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:22 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:22 minidsp-shd volumio[635]: info: Feb 24 19:20:22 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:22 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:22 minidsp-shd volumio[635]: info: Feb 24 19:20:22 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:22 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:22 minidsp-shd volumio[635]: info: Feb 24 19:20:22 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:22 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:22 minidsp-shd volumio[635]: info: Feb 24 19:20:22 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:22 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:22 minidsp-shd volumio[635]: info: ------------------------------ 32ms Feb 24 19:20:22 minidsp-shd volumio[635]: info: sendMpdCommand status took 28 milliseconds Feb 24 19:20:22 minidsp-shd volumio[635]: info: ------------------------------ 27ms Feb 24 19:20:22 minidsp-shd volumio[635]: info: sendMpdCommand status took 22 milliseconds Feb 24 19:20:22 minidsp-shd volumio[635]: info: ------------------------------ 21ms Feb 24 19:20:22 minidsp-shd volumio[635]: info: sendMpdCommand status took 17 milliseconds Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:22 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 10 milliseconds Feb 24 19:20:22 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 10 milliseconds Feb 24 19:20:22 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 10 milliseconds Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:22 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 1 Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":249,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"552 Kbps","isStreaming":false,"title":"46201113","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/46201113","trackType":"qobuz"} Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: CURRENT POSITION 1 Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService play Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus play Feb 24 19:20:22 minidsp-shd volumio[635]: info: Received an update from plugin. extracting info from payload Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 1 Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":249,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"552 Kbps","isStreaming":false,"title":"46201113","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/46201113","trackType":"qobuz"} Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: CURRENT POSITION 1 Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService play Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus play Feb 24 19:20:22 minidsp-shd volumio[635]: info: Received an update from plugin. extracting info from payload Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 1 Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":249,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"552 Kbps","isStreaming":false,"title":"46201113","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/46201113","trackType":"qobuz"} Feb 24 19:20:22 minidsp-shd volumio[635]: verbose: CURRENT POSITION 1 Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService play Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus play Feb 24 19:20:22 minidsp-shd volumio[635]: info: Received an update from plugin. extracting info from payload Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:22 minidsp-shd volumio[635]: info: ------------------------------ 194ms Feb 24 19:20:22 minidsp-shd volumio[635]: info: ------------------------------ 189ms Feb 24 19:20:22 minidsp-shd volumio[635]: info: ------------------------------ 184ms Feb 24 19:20:22 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:22 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:22 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:22 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:22 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:22 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:23 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:23 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 19:20:23 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:23 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:23 minidsp-shd volumio[635]: STREAMING PROXY: Client dropped request, destroying Feb 24 19:20:23 minidsp-shd volumio[635]: error: Failed request for metavolumio API Feb 24 19:20:23 minidsp-shd volumio[635]: info: Getting Spotify volume Feb 24 19:20:23 minidsp-shd volumio[635]: (node:635) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:23 minidsp-shd volumio[635]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 19:20:23 minidsp-shd volumio[635]: (node:635) 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: 746) Feb 24 19:20:23 minidsp-shd volumio[635]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Feb 24 19:20:23 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:20:24 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:24 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:24 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2247. Feb 24 19:20:24 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:24 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:24 minidsp-shd go-librespot[29970]: Librespot-go daemon starting... Feb 24 19:20:24 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:24+01:00" level=info msg="generated new device id: a8bb5d7727e46c26325469dcc0837eb0b0e1c864" Feb 24 19:20:24 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:24+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:24 minidsp-shd volumio[635]: error: Failed request for metavolumio API Feb 24 19:20:24 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:24+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:20:24 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:24+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:20:24 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:24+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:20:24 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:24+01:00" level=debug msg="zeroconf server listening on port 42829" Feb 24 19:20:24 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:24+01:00" level=debug msg="obtained new client token: AABDvOAJ4QXwyuEh7brQGjTkBxalfQSgFULAkf3MJFpxuKbaOiDRB04EtJElz7PjM2xmXMkmrl0MDlJ1rhHT1oRiDvnyfKko1E672Oz6hmFq2DzA+tszw8nfAGASNHjIftzG2QWhViYm+ir3TMbbKUiZIXhmxVE6feFReAR77iJf48ul70xaxHodCjmCXAQ2d/U60q5SgXBVCJHrlQeUFrBEYnUXeYhj/LJZWl3r90Nzv/2xAw0DUCeBpcWRZQ==" Feb 24 19:20:25 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:25+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Feb 24 19:20:25 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:25+01:00" level=info msg="connected to ap-gew4.spotify.com:443" Feb 24 19:20:25 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:25+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:25 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:25+01:00" level=debug msg="completed challenge" Feb 24 19:20:25 minidsp-shd go-librespot[29970]: time="2025-02-24T19:20:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:25 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:25 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:27 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:27 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:28 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 24 19:20:28 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 24 19:20:28 minidsp-shd volumio[635]: info: Discovery: Getting this device information Feb 24 19:20:28 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:20:28 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 24 19:20:28 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:28 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2248. Feb 24 19:20:28 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:28 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:29 minidsp-shd go-librespot[29986]: Librespot-go daemon starting... Feb 24 19:20:29 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:29+01:00" level=info msg="generated new device id: 6835bcbf956f64022fffc5a167f57af8dcb9be81" Feb 24 19:20:29 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:29+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:29 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:20:29 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:29+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:20:29 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:29+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:20:29 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:29+01:00" level=debug msg="zeroconf server listening on port 43171" Feb 24 19:20:29 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:29+01:00" level=debug msg="obtained new client token: AAAE1nynBE+1JR1C7olYxoh/1jRrksknFzMtHJBeXA3mn+1x5+AJ1/KM73p4ITga0khCkcikC1VF6jE/fKahrff/hrawndiVccZq70Xe/A/reAcENi0J46/4p5v0TLzK7/IM0MYqZqEtrhtN4ZLMCcW6MPqdaB51LEawPvc4/bMUGdqCOjbM6Ec1yOexs4wezgSvEAapNFCvy4R73+0yWpBAe84MP8dj7vuozfDOtKDi08U+3+YhG/dw3GCDjQ==" Feb 24 19:20:29 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:29+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:29 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:29+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:29 minidsp-shd volumio[635]: info: Preload queue cleared Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreStateMachine::ClearQueue Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreStateMachine::stop Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreStateMachine::stPlaybackTimer Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreStateMachine::updateTrackBlock Feb 24 19:20:29 minidsp-shd volumio[635]: info: CorePlayQueue::getTrackBlock Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:29 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 1 Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreStateMachine::serviceStop Feb 24 19:20:29 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 1 Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreCommandRouter::serviceStop Feb 24 19:20:29 minidsp-shd volumio[635]: info: [1740421229890] ControllerQobuz::stop Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 24 19:20:29 minidsp-shd volumio[635]: info: ControllerMpd::stop Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand stop Feb 24 19:20:29 minidsp-shd volumio[635]: info: CorePlayQueue::clearPlayQueue Feb 24 19:20:29 minidsp-shd volumio[635]: info: CorePlayQueue::saveQueue Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushQueue Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreStateMachine::addQueueItems Feb 24 19:20:29 minidsp-shd volumio[635]: info: CorePlayQueue::addQueueItems Feb 24 19:20:29 minidsp-shd volumio[635]: info: Preload queue cleared Feb 24 19:20:29 minidsp-shd volumio[635]: info: Adding Item to queue: qobuz://album/fmfnwvpr5yppb Feb 24 19:20:29 minidsp-shd volumio[635]: info: Exploding uri qobuz://album/fmfnwvpr5yppb in service qobuz Feb 24 19:20:29 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:29 minidsp-shd volumio[635]: info: Feb 24 19:20:29 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:29 minidsp-shd volumio[635]: info: sendMpdCommand stop took 52 milliseconds Feb 24 19:20:29 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:29 minidsp-shd volumio[635]: info: Feb 24 19:20:29 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:29 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:29 minidsp-shd volumio[635]: info: Feb 24 19:20:29 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:29 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:29 minidsp-shd volumio[635]: info: sendMpdCommand status took 14 milliseconds Feb 24 19:20:29 minidsp-shd volumio[635]: info: sendMpdCommand status took 9 milliseconds Feb 24 19:20:29 minidsp-shd volumio[635]: info: sendMpdCommand status took 6 milliseconds Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:29 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 10 milliseconds Feb 24 19:20:29 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 9 milliseconds Feb 24 19:20:29 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 8 milliseconds Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:29 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:29 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 19:20:29 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 1 Feb 24 19:20:30 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"46201113","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/46201113","trackType":"qobuz"} Feb 24 19:20:30 minidsp-shd volumio[635]: verbose: CURRENT POSITION 1 Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService stop Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus stop Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: No code Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 1 Feb 24 19:20:30 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"46201113","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/46201113","trackType":"qobuz"} Feb 24 19:20:30 minidsp-shd volumio[635]: verbose: CURRENT POSITION 1 Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService stop Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus stop Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: No code Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 1 Feb 24 19:20:30 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"46201113","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/46201113","trackType":"qobuz"} Feb 24 19:20:30 minidsp-shd volumio[635]: verbose: CURRENT POSITION 1 Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService stop Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus stop Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: No code Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:30 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:30+01:00" level=debug msg="completed challenge" Feb 24 19:20:30 minidsp-shd volumio[635]: info: ------------------------------ 184ms Feb 24 19:20:30 minidsp-shd volumio[635]: info: ------------------------------ 179ms Feb 24 19:20:30 minidsp-shd volumio[635]: info: ------------------------------ 177ms Feb 24 19:20:30 minidsp-shd go-librespot[29986]: time="2025-02-24T19:20:30+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:30 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:30 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:30 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:30 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:30 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:30 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:30 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:30 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:30 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:30 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:30 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:30 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:30 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:30 minidsp-shd volumio[635]: info: explodeUri took 855 milliseconds Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushQueue Feb 24 19:20:30 minidsp-shd volumio[635]: info: CorePlayQueue::saveQueue Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::updateTrackBlock Feb 24 19:20:30 minidsp-shd volumio[635]: info: CorePlayQueue::getTrackBlock Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPlay Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::play index 0 Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::stop Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::play index undefined Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 19:20:30 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 0 Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreStateMachine::startPlaybackTimer Feb 24 19:20:30 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 0 Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetVisibleSources Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 24 19:20:30 minidsp-shd volumio[635]: info: [1740421230792] ControllerQobuz::clearAddPlayTrack Feb 24 19:20:30 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand stop Feb 24 19:20:30 minidsp-shd volumio[635]: info: sendMpdCommand stop took 10 milliseconds Feb 24 19:20:30 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand clear Feb 24 19:20:30 minidsp-shd volumio[635]: info: Feb 24 19:20:30 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:30 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:30 minidsp-shd volumio[635]: info: sendMpdCommand clear took 5 milliseconds Feb 24 19:20:30 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/117818194" Feb 24 19:20:30 minidsp-shd volumio[635]: info: Feb 24 19:20:30 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:30 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:30 minidsp-shd volumio[635]: STREAMING PROXY: Handling url /?data=qobuz://song/117818194 Feb 24 19:20:30 minidsp-shd volumio[635]: info: Feb 24 19:20:30 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:30 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:30 minidsp-shd volumio[635]: error: updateQueue error: null Feb 24 19:20:30 minidsp-shd volumio[635]: info: ------------------------------ 17ms Feb 24 19:20:30 minidsp-shd volumio[635]: info: Executing endpoint getStreamUrlqobuz Feb 24 19:20:30 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Feb 24 19:20:31 minidsp-shd volumio[635]: info: getStreamUrl took 468 milliseconds Feb 24 19:20:31 minidsp-shd volumio[635]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=3504051&eid=117818194&fmt=7&profile=raw&app_id=539451548&cid=2505592&etsp=1740424831&hmac=oylDnLrYl4b9CQQEzErXG7jIvpU Feb 24 19:20:31 minidsp-shd volumio[635]: STREAMING PROXY: Response: 200, length: 38684352 Feb 24 19:20:31 minidsp-shd volumio[635]: STREAMING PROXY: Client dropped request, destroying Feb 24 19:20:31 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/117818194" Feb 24 19:20:31 minidsp-shd volumio[635]: error: updateQueue error: null Feb 24 19:20:31 minidsp-shd volumio[635]: error: updateQueue error: null Feb 24 19:20:31 minidsp-shd volumio[635]: info: Feb 24 19:20:31 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:31 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:31 minidsp-shd volumio[635]: info: ------------------------------ 1013ms Feb 24 19:20:31 minidsp-shd volumio[635]: info: ------------------------------ 1008ms Feb 24 19:20:31 minidsp-shd volumio[635]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/117818194" took 11 milliseconds Feb 24 19:20:31 minidsp-shd volumio[635]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 24 19:20:31 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand play Feb 24 19:20:31 minidsp-shd volumio[635]: info: Feb 24 19:20:31 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:31 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:31 minidsp-shd volumio[635]: STREAMING PROXY: Handling url /?data=qobuz://song/117818194 Feb 24 19:20:31 minidsp-shd volumio[635]: info: Feb 24 19:20:31 minidsp-shd volumio[635]: ---------------------------- MPD announces system playlist update Feb 24 19:20:31 minidsp-shd volumio[635]: info: Ignoring MPD Status Update Feb 24 19:20:31 minidsp-shd volumio[635]: info: ------------------------------ 22ms Feb 24 19:20:31 minidsp-shd volumio[635]: info: sendMpdCommand play took 15 milliseconds Feb 24 19:20:31 minidsp-shd volumio[635]: info: ------------------------------ 13ms Feb 24 19:20:31 minidsp-shd volumio[635]: info: ------------------------------ 9ms Feb 24 19:20:31 minidsp-shd volumio[635]: info: Executing endpoint getStreamUrlqobuz Feb 24 19:20:31 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Feb 24 19:20:32 minidsp-shd volumio[635]: info: getStreamUrl took 493 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=3504051&eid=117818194&fmt=7&profile=raw&app_id=539451548&cid=2505592&etsp=1740424832&hmac=YA3YeuzAQdxAvyhDLwk9quF6k8g Feb 24 19:20:32 minidsp-shd volumio[635]: STREAMING PROXY: Response: 200, length: 38684352 Feb 24 19:20:32 minidsp-shd volumio[635]: info: Feb 24 19:20:32 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:32 minidsp-shd volumio[635]: info: Feb 24 19:20:32 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:32 minidsp-shd volumio[635]: info: Feb 24 19:20:32 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand status took 11 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand status took 6 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:32 minidsp-shd volumio[635]: info: Feb 24 19:20:32 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:32 minidsp-shd volumio[635]: info: Feb 24 19:20:32 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand status took 49 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 48 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 57 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand status took 45 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand status took 37 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 0 Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":201,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"117818194","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/117818194","trackType":"qobuz"} Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: CURRENT POSITION 0 Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService play Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus stop Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 0 Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":201,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"117818194","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/117818194","trackType":"qobuz"} Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: CURRENT POSITION 0 Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService play Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus play Feb 24 19:20:32 minidsp-shd volumio[635]: info: Received an update from plugin. extracting info from payload Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: ------------------------------ 176ms Feb 24 19:20:32 minidsp-shd volumio[635]: info: ------------------------------ 210ms Feb 24 19:20:32 minidsp-shd volumio[635]: info: Feb 24 19:20:32 minidsp-shd volumio[635]: ---------------------------- MPD announces state update: player Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::getState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand status Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 143 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 134 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 126 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: info: sendMpdCommand status took 12 milliseconds Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::parseState Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 0 Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":201,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"117818194","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/117818194","trackType":"qobuz"} Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: CURRENT POSITION 0 Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService play Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus play Feb 24 19:20:32 minidsp-shd volumio[635]: info: Received an update from plugin. extracting info from payload Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 0 Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":201,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"117818194","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/117818194","trackType":"qobuz"} Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: CURRENT POSITION 0 Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService play Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus play Feb 24 19:20:32 minidsp-shd volumio[635]: info: Received an update from plugin. extracting info from payload Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 0 Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":201,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"117818194","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/117818194","trackType":"qobuz"} Feb 24 19:20:32 minidsp-shd volumio[635]: verbose: CURRENT POSITION 0 Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService play Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus play Feb 24 19:20:32 minidsp-shd volumio[635]: info: Received an update from plugin. extracting info from payload Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:32 minidsp-shd volumio[635]: info: ------------------------------ 461ms Feb 24 19:20:32 minidsp-shd volumio[635]: info: ------------------------------ 445ms Feb 24 19:20:32 minidsp-shd volumio[635]: info: ------------------------------ 439ms Feb 24 19:20:33 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:33 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:33 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:33 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:33 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:33 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:33 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:33 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:33 minidsp-shd volumio[635]: info: sendMpdCommand playlistinfo took 369 milliseconds Feb 24 19:20:33 minidsp-shd volumio[635]: verbose: ControllerMpd::parseTrackInfo Feb 24 19:20:33 minidsp-shd volumio[635]: info: ControllerMpd::pushState Feb 24 19:20:33 minidsp-shd volumio[635]: info: CoreCommandRouter::servicePushState Feb 24 19:20:33 minidsp-shd volumio[635]: info: CorePlayQueue::getTrack 0 Feb 24 19:20:33 minidsp-shd volumio[635]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1234,"duration":201,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1475 Kbps","isStreaming":false,"title":"117818194","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/117818194","trackType":"qobuz"} Feb 24 19:20:33 minidsp-shd volumio[635]: verbose: CURRENT POSITION 0 Feb 24 19:20:33 minidsp-shd volumio[635]: info: CoreStateMachine::syncState stateService play Feb 24 19:20:33 minidsp-shd volumio[635]: info: CoreStateMachine::syncState currentStatus play Feb 24 19:20:33 minidsp-shd volumio[635]: info: Received an update from plugin. extracting info from payload Feb 24 19:20:33 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:33 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 19:20:33 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:33 minidsp-shd volumio[635]: info: CoreStateMachine::pushState Feb 24 19:20:33 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioPushState Feb 24 19:20:33 minidsp-shd volumio[635]: info: ------------------------------ 470ms Feb 24 19:20:33 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:33 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:33 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:33 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2249. Feb 24 19:20:33 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:33 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:33 minidsp-shd go-librespot[30009]: Librespot-go daemon starting... Feb 24 19:20:33 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:33 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:33+01:00" level=info msg="generated new device id: 63a82d365868252cda6d4232b1362b457cbca779" Feb 24 19:20:33 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:33+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:33 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:33+01:00" level=debug msg="new websocket client" Feb 24 19:20:33 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket established Feb 24 19:20:34 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:34+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 19:20:34 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:34+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 19:20:34 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:34+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 19:20:34 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:34+01:00" level=debug msg="zeroconf server listening on port 38293" Feb 24 19:20:34 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:34+01:00" level=debug msg="obtained new client token: AAAXG5bOt7hp/Uy7XtyZGEliQXKvkhQzuNsHwavUbufc/orHS20wTvvOLn63rew3HhjenpwD5zOLMfsPgz/LHTHZBwLpMakhCSTub8+3xHqFX6VSJvkzqGRS3/zjyePA5N2BC0dSlzevltPIl8jXytq7PygfRiW2DDw2ka0V0fOkTVm9m9cRE6DqYOIqqF4/LqZthi9eQCCjr2GQvXKsCqalBC73KGbKzajjTNfl+FyEax1uYgTedNyu0dT8bg==" Feb 24 19:20:34 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:34+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:34 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:34+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:35 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:35+01:00" level=debug msg="completed challenge" Feb 24 19:20:35 minidsp-shd go-librespot[30009]: time="2025-02-24T19:20:35+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:35 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:35 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:35 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket closed Feb 24 19:20:36 minidsp-shd volumio[635]: info: Getting Spotify volume Feb 24 19:20:36 minidsp-shd volumio[635]: (node:635) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:36 minidsp-shd volumio[635]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 19:20:36 minidsp-shd volumio[635]: (node:635) 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: 747) Feb 24 19:20:36 minidsp-shd volumio[635]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Feb 24 19:20:36 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:20:36 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:37 minidsp-shd volumio[635]: STREAMING PROXY: Client dropped request, destroying Feb 24 19:20:38 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:38 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:38 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:38 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2250. Feb 24 19:20:38 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:38 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:38 minidsp-shd go-librespot[30030]: Librespot-go daemon starting... Feb 24 19:20:38 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:38+01:00" level=info msg="generated new device id: 0108d73f216a5e230d0b0259dbf3751bc211fdaf" Feb 24 19:20:38 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:38+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:38 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:38+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:20:38 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:38+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:20:38 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:38+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:20:38 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:38+01:00" level=debug msg="zeroconf server listening on port 41337" Feb 24 19:20:38 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:38+01:00" level=debug msg="obtained new client token: AAAzuNWEAl7mpqPicCgend2bN1CFUH+eMkVlqj5m652r0oRT+YLWbGO4AFQrNRzJN4rlV1+kNrUM1pqTZunwo9URjFTRnoGRZkZntXF7hFJE/28j9KUeGGT4gnj6xmIYz0EFeQI5gEZIGt7ii/Mea83FQGkFSF93P84y2zrDDhF5eR8i99Z2AC4R4/kS3eMj/5LZKGYmLw0S6eB7iQKul+QDmm/NenGU2Y3vZEQ/MnX+/KCk8RIQoFIg0PhPKw==" Feb 24 19:20:39 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:39+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:39 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:39+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:39 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:39+01:00" level=debug msg="completed challenge" Feb 24 19:20:39 minidsp-shd go-librespot[30030]: time="2025-02-24T19:20:39+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:39 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:39 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:41 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:41 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:42 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:20:42 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:42 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2251. Feb 24 19:20:42 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:42 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:42 minidsp-shd go-librespot[30046]: Librespot-go daemon starting... Feb 24 19:20:42 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:42+01:00" level=info msg="generated new device id: 92bd5073aa79b5d39b4ad93dbfedc46494004116" Feb 24 19:20:42 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:42+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:43 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:43+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:20:43 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:43+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:20:43 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:43+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:20:43 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:43+01:00" level=debug msg="zeroconf server listening on port 43585" Feb 24 19:20:43 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:43+01:00" level=debug msg="obtained new client token: AABLNHQHL1RCn4C6p7FX2AsE+c7Tx8yK58Qeo1GXUgMSXd7y+vkv4jVddwaIRNRuCEezIxUxd0YlfZp2vPu6VcmtvTqtskgsBn1fHxyH0xWnS0IpXACUPklg377pEEFLNRnIJNRSOQlPE2Ze6Xa9fFYokFrOK/QQ4oDdUzpQw6VxZ+CVS11WXnsNl4Ne7pm82iLaWJKxHfkWDB2lkwUhWrJpJdRRChWqzBpjwZfbMSHE92C2qjLhPYWsfyM=" Feb 24 19:20:43 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:43+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:43 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:43+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:43 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:43+01:00" level=debug msg="completed challenge" Feb 24 19:20:43 minidsp-shd go-librespot[30046]: time="2025-02-24T19:20:43+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:43 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:43 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:44 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:44 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:44 minidsp-shd volumio[635]: info: Executing endpoint metavolumio Feb 24 19:20:44 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 24 19:20:44 minidsp-shd volumio[635]: info: Executing endpoint metavolumio Feb 24 19:20:44 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 24 19:20:44 minidsp-shd volumio[635]: info: Executing endpoint metavolumio Feb 24 19:20:44 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 24 19:20:46 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:46 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2252. Feb 24 19:20:46 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:46 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:47 minidsp-shd go-librespot[30062]: Librespot-go daemon starting... Feb 24 19:20:47 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:47+01:00" level=info msg="generated new device id: 9d5be044e4355c3db9c59a2c80d66d0f684a143f" Feb 24 19:20:47 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:47+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:47 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:47+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 19:20:47 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:47+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 19:20:47 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:47+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 19:20:47 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:47+01:00" level=debug msg="zeroconf server listening on port 39453" Feb 24 19:20:47 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:47 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:47+01:00" level=debug msg="new websocket client" Feb 24 19:20:47 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket established Feb 24 19:20:47 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:47+01:00" level=debug msg="obtained new client token: AABuZicDNCfym3qckNYPwceBCJQM8M4qy2msd6CKtP64MfKTaKJq5NqRHxukvzT+o8p24gvXb81xZBndWhMN8EpfrawM7k9pJ0W7PEY3Nz2lD2245ZYEzqrTHyOMJMhCk6Ri+gFUBcek6hkhNZ6hmFEXYRWno9akqKHPATiIhOka59jtt3+RJlCdLZK58SapN+JLaNxIh1G+ufMvawvFRzy2gmgabR5AqEuMs2iCPALCG/HcDyuut2peUUl/mA==" Feb 24 19:20:47 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:47+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:47 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:47+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:48 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:48+01:00" level=debug msg="completed challenge" Feb 24 19:20:48 minidsp-shd go-librespot[30062]: time="2025-02-24T19:20:48+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:48 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:48 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:48 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket closed Feb 24 19:20:50 minidsp-shd volumio[635]: info: Getting Spotify volume Feb 24 19:20:50 minidsp-shd volumio[635]: (node:635) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:50 minidsp-shd volumio[635]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 19:20:50 minidsp-shd volumio[635]: (node:635) 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: 748) Feb 24 19:20:50 minidsp-shd volumio[635]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Feb 24 19:20:50 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:20:50 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:20:51 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:51 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:51 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:51 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2253. Feb 24 19:20:51 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:51 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:51 minidsp-shd go-librespot[30078]: Librespot-go daemon starting... Feb 24 19:20:51 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:51+01:00" level=info msg="generated new device id: f92e8efeccc2e8ae9df0bba6114034668703f7e6" Feb 24 19:20:51 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:51+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:51 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:51+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:20:51 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:51+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:20:51 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:51+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:20:51 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:51+01:00" level=debug msg="zeroconf server listening on port 45363" Feb 24 19:20:51 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:51+01:00" level=debug msg="obtained new client token: AACftO6f4lY5RsEPy4IEOFGJv29tlm3Uhb2STBliyWKPSvJIAmRG+QNlNHgItnoFPGAe2XogHnCBU5gHuZwRLTMcHnkLz6zT65J7Oz6UJLE+b2wQUVHvrZ5z+gXZcANZfVflgbEZTjxEpAXHvmQtzD1ZpczTnLLXu6705ytUmkzTwaZSME3t3J10+iRLOaztHu+bU6a1HCCa7zlBgSIoPvngZTSaSFZp0cP32tIBkWfyVfevJBhnyvAC1w2xhw==" Feb 24 19:20:51 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:51+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:51 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:51+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:52 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:52+01:00" level=debug msg="completed challenge" Feb 24 19:20:52 minidsp-shd go-librespot[30078]: time="2025-02-24T19:20:52+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:52 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:52 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:54 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:54 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:55 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:55 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2254. Feb 24 19:20:55 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:55 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:55 minidsp-shd go-librespot[30094]: Librespot-go daemon starting... Feb 24 19:20:55 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:55+01:00" level=info msg="generated new device id: 1cd0c7d2f06066c4fa556a433fee1847fe285c65" Feb 24 19:20:55 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:55+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:20:55 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:55+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 19:20:55 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:55+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 19:20:55 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:55+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 19:20:55 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:55+01:00" level=debug msg="zeroconf server listening on port 34317" Feb 24 19:20:55 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:55+01:00" level=debug msg="obtained new client token: AAAoykFybaogxn2NsTSo+d7eMyXNpOdzDJNUaEcJA9oHuEAQJEia7bjdKxwloBOONMHfwihmVS6CVO4GZA3wRhsjciTlv95epn6MzG93stnTRrLYmtwqAgCMhFKZK0irnBlMh0Bk1L0ymL/MXfHJuXyLirpPg1A/Dc0gPIAM04Lpj84ttHaQYMKgLxHEqzLD2ShbP6XwHmHA1DCQd+czS3+m1wSzqBW08vJfaPCmnqNLcTss0VaCRWmE/1idhw==" Feb 24 19:20:56 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:56+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:20:56 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:56+01:00" level=debug msg="completed keyexchange" Feb 24 19:20:56 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:56+01:00" level=debug msg="completed challenge" Feb 24 19:20:56 minidsp-shd go-librespot[30094]: time="2025-02-24T19:20:56+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:20:56 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:20:56 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:20:57 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:20:57 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:20:58 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 24 19:20:58 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 24 19:20:58 minidsp-shd volumio[635]: info: Discovery: Getting this device information Feb 24 19:20:58 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:20:58 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 24 19:20:59 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:20:59 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2255. Feb 24 19:20:59 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:20:59 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:20:59 minidsp-shd go-librespot[30150]: Librespot-go daemon starting... Feb 24 19:20:59 minidsp-shd go-librespot[30150]: time="2025-02-24T19:20:59+01:00" level=info msg="generated new device id: 541b582e4e37e1e7a95f8b5d3c5a356c67fce94b" Feb 24 19:20:59 minidsp-shd go-librespot[30150]: time="2025-02-24T19:20:59+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:21:00 minidsp-shd go-librespot[30150]: time="2025-02-24T19:21:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:21:00 minidsp-shd go-librespot[30150]: time="2025-02-24T19:21:00+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:21:00 minidsp-shd go-librespot[30150]: time="2025-02-24T19:21:00+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:21:00 minidsp-shd go-librespot[30150]: time="2025-02-24T19:21:00+01:00" level=debug msg="zeroconf server listening on port 34795" Feb 24 19:21:00 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:00 minidsp-shd go-librespot[30150]: time="2025-02-24T19:21:00+01:00" level=debug msg="new websocket client" Feb 24 19:21:00 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket established Feb 24 19:21:00 minidsp-shd go-librespot[30150]: time="2025-02-24T19:21:00+01:00" level=debug msg="obtained new client token: AAAVRDQ4XAvOJWFkjfdMxoaknBdWNBNMl5dZ2HBGZW6xiFj3WYC20FNqu8nbS22bawPdyEIDCRhRhZ1gviXPqzu0LA0Y4+ZKo4BW/tbwxi6zpzhDr1TU1f+z6jp03SDlZRzOXUBFY/p/fsfMszFbmDX2YWoPL0XdE8V6aY+oCIk9Kyiftkeqh+eb9UW80SKdWOKZdAJOp9s/R+q4OaH8Sr0vEsZKf8n2LzRNAj1e4s8rs677JQxcw8xkfBY=" Feb 24 19:21:00 minidsp-shd go-librespot[30150]: time="2025-02-24T19:21:00+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:21:01 minidsp-shd go-librespot[30150]: time="2025-02-24T19:21:01+01:00" level=debug msg="completed keyexchange" Feb 24 19:21:01 minidsp-shd go-librespot[30150]: time="2025-02-24T19:21:01+01:00" level=debug msg="completed challenge" Feb 24 19:21:01 minidsp-shd go-librespot[30150]: time="2025-02-24T19:21:01+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:21:01 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:21:01 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:21:01 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket closed Feb 24 19:21:03 minidsp-shd volumio[635]: info: Getting Spotify volume Feb 24 19:21:03 minidsp-shd volumio[635]: (node:635) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:03 minidsp-shd volumio[635]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 19:21:03 minidsp-shd volumio[635]: (node:635) 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: 749) Feb 24 19:21:03 minidsp-shd volumio[635]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Feb 24 19:21:03 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:21:03 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:21:04 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:04 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:04 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:21:04 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2256. Feb 24 19:21:04 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:21:04 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:21:05 minidsp-shd go-librespot[30169]: Librespot-go daemon starting... Feb 24 19:21:05 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:05+01:00" level=info msg="generated new device id: 79bdd986d2835b4210d40cded47f00b0a8a06546" Feb 24 19:21:05 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:05+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:21:05 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:05+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:21:05 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:05+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:21:05 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:05+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:21:05 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:05+01:00" level=debug msg="zeroconf server listening on port 46799" Feb 24 19:21:05 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:05+01:00" level=debug msg="obtained new client token: AABstHPWAgiptUMANKL/TxW4z4aroYi38r68jJK5OHo44Ar5pkO4hQeRUv2HpDUEQb3rQhKT/vm8wrXk8t7i0V6p88e15yW0zVACBktbir5MohEXf1EASD69rhDCmX0gx4Vei7S8YIPlbhknZhIAWh84hPAAgynOXmQvr/dZgYLeOik14xBfE81Tse5OYPpCMqX0Fj1f87+ffgh4AjiJ3HqpXNhSQhL2osYNwbeyjTbOgmIzxntWWRv+imCREQ==" Feb 24 19:21:05 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:05+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:21:06 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:06+01:00" level=debug msg="completed keyexchange" Feb 24 19:21:07 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:07+01:00" level=debug msg="completed challenge" Feb 24 19:21:07 minidsp-shd go-librespot[30169]: time="2025-02-24T19:21:07+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:21:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:21:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:21:07 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:07 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:10 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:21:10 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2257. Feb 24 19:21:10 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:21:10 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:21:10 minidsp-shd go-librespot[30187]: Librespot-go daemon starting... Feb 24 19:21:10 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:10+01:00" level=info msg="generated new device id: 942970e7ce2eca893c5b1cae41ebb5b5bcd1c4df" Feb 24 19:21:10 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:10+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:21:10 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:10+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:21:10 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:10+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:21:10 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:10+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:21:10 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:10+01:00" level=debug msg="zeroconf server listening on port 33049" Feb 24 19:21:10 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:10 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:10+01:00" level=debug msg="new websocket client" Feb 24 19:21:10 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket established Feb 24 19:21:10 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:10+01:00" level=debug msg="obtained new client token: AAClgiUpmMYllOnjLg4gQPAW4CX9xGhglHlcK9QDghmS6PCG6OXKIrwZIcw7NEs51X9sge0fKeSynL4tu4EYoxppHKxJFXyP+kiEVyWPX1WlwMnhmuUMZtghqQGT4QUFVe1k1MvZCyhdhpWFhG9A2EavfePdBKsckg9sLuqY+bQOjW98ELdPY53HHMuKG9MQ9YAtD1LY1urhJ9AEhOilogfZcEQpcZIdqSy3Sub8DSpkeL7e8JPbwZ1Ax99wBw==" Feb 24 19:21:10 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:10+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:21:10 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:10+01:00" level=debug msg="completed keyexchange" Feb 24 19:21:11 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:11+01:00" level=debug msg="completed challenge" Feb 24 19:21:11 minidsp-shd go-librespot[30187]: time="2025-02-24T19:21:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:21:11 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket closed Feb 24 19:21:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:21:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:21:13 minidsp-shd volumio[635]: info: Getting Spotify volume Feb 24 19:21:13 minidsp-shd volumio[635]: (node:635) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:13 minidsp-shd volumio[635]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 19:21:13 minidsp-shd volumio[635]: (node:635) 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: 750) Feb 24 19:21:13 minidsp-shd volumio[635]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Feb 24 19:21:13 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:21:13 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:21:14 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:14 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:21:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2258. Feb 24 19:21:14 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:21:14 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:21:14 minidsp-shd go-librespot[30203]: Librespot-go daemon starting... Feb 24 19:21:14 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:14+01:00" level=info msg="generated new device id: 96208ed6bc0bc5a0d47430338de2efe073bfb2fb" Feb 24 19:21:14 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:14+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:21:14 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:14+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:21:14 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:14+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:21:14 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:14+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:21:14 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:14+01:00" level=debug msg="zeroconf server listening on port 35039" Feb 24 19:21:15 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:15+01:00" level=debug msg="obtained new client token: AABrTU26kQb4zJyGD55ucwmbR3LktVnh10yZ7WOA7Vc2DOgNmpYM/RBf+/9ZFyClOdWK4uDsv2IBEIQI0NEahZbNTbEAjWkFE1BXSOz+CDCQQaD4xdp8XZ1xQ4OTn7R9S989w931q4GOazYOKa5aANS2L3wqbHcxzm9XGh5zsZva/zcBvMhzqrNjrMMEVp2IszUCtvgWJfBhdWJhCXMQ/t0kzxAZtBLX2tDocWtsVoJRPHitaiSahZXM" Feb 24 19:21:15 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:15+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:21:15 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:15+01:00" level=debug msg="completed keyexchange" Feb 24 19:21:15 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:15+01:00" level=debug msg="completed challenge" Feb 24 19:21:15 minidsp-shd go-librespot[30203]: time="2025-02-24T19:21:15+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:21:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:21:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:21:17 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:17 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:21:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2259. Feb 24 19:21:18 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:21:18 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:21:18 minidsp-shd go-librespot[30223]: Librespot-go daemon starting... Feb 24 19:21:18 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:18+01:00" level=info msg="generated new device id: 0cc83c59e62ea3d5c04a454ac59eab160b123015" Feb 24 19:21:18 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:18+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:21:19 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:21:19 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:19+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:21:19 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:19+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:21:19 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:19+01:00" level=debug msg="zeroconf server listening on port 38453" Feb 24 19:21:19 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:19+01:00" level=debug msg="obtained new client token: AACxKHpM3yA7RMbXa8KkGs19+lgV0vod8hioKCjfna1tDyqD+Yc8n9g3MSHdMZlb7b1k0Nm7hea8tkXMFD5L9iSDamJ04vWO4lqKCQTPhxwdtRt8eBy6h3KqxfyrZL38KZ0UGHfr23tQYda7mXhTxrT1LGEkqYgqUuUmH0lqU03TQPlneFzdp5ReZ1w4pU6J9ss/+I/KGoPUhSPU0GJBgTLyu7XmfNl2Tqo9RjyaC4XlH6b7Mf4YC4YBkPo=" Feb 24 19:21:19 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:19+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:21:19 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:19+01:00" level=debug msg="completed keyexchange" Feb 24 19:21:19 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:19+01:00" level=debug msg="completed challenge" Feb 24 19:21:19 minidsp-shd go-librespot[30223]: time="2025-02-24T19:21:19+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:21:19 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:21:19 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:21:20 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:20 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:22 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:21:22 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2260. Feb 24 19:21:22 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:21:22 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:21:23 minidsp-shd go-librespot[30240]: Librespot-go daemon starting... Feb 24 19:21:23 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:23+01:00" level=info msg="generated new device id: 71925568357e969b03bd5c68d822fb4a97eee351" Feb 24 19:21:23 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:23+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:21:23 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:23+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:21:23 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:23+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:21:23 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:23+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:21:23 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:23+01:00" level=debug msg="zeroconf server listening on port 34263" Feb 24 19:21:23 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:23 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:23+01:00" level=debug msg="new websocket client" Feb 24 19:21:23 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket established Feb 24 19:21:23 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:23+01:00" level=debug msg="obtained new client token: AACA77NBmQNFnOtPd5RuoWZBuMXj+de5ZudrnuobejZjQCt1ucg9Pf0NabU2pWp3nkDzgWiHpUqOrqsVVV0AJRh6okz5Clvlddphfb5GFQPkHGBD5GPkc0VRK5cMezx7Fc+tQzyD2jPs9gk+zfscTrauRS0ZfEC6VSUohYE8nLgoifkkHmAwXIcPOt6Pewt4H7SpsA1cCUBp5Ske2cpHMavES3XO8Duv249KIdmLb0bPAxwE7OqA17wfDqOylg==" Feb 24 19:21:23 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:23+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:21:23 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:23+01:00" level=debug msg="completed keyexchange" Feb 24 19:21:24 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:24+01:00" level=debug msg="completed challenge" Feb 24 19:21:24 minidsp-shd go-librespot[30240]: time="2025-02-24T19:21:24+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:21:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:21:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:21:24 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket closed Feb 24 19:21:26 minidsp-shd volumio[635]: info: Getting Spotify volume Feb 24 19:21:26 minidsp-shd volumio[635]: (node:635) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:26 minidsp-shd volumio[635]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 19:21:26 minidsp-shd volumio[635]: (node:635) 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: 751) Feb 24 19:21:26 minidsp-shd volumio[635]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Feb 24 19:21:26 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:21:26 minidsp-shd volumio[635]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 19:21:27 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:27 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:21:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2261. Feb 24 19:21:27 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:21:27 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:21:27 minidsp-shd go-librespot[30256]: Librespot-go daemon starting... Feb 24 19:21:27 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:27+01:00" level=info msg="generated new device id: 554bfe7d298ca9c0c4a28dffa95c7e5f97497299" Feb 24 19:21:27 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:27+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:21:27 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:27+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:21:27 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:27+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:21:27 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:27+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:21:27 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:27+01:00" level=debug msg="zeroconf server listening on port 37957" Feb 24 19:21:27 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:27+01:00" level=debug msg="obtained new client token: AACSovpIoMjy2xYPCti5mHd7VNKMOQo5yHVQN4HeQrqdWeRf4vJx4CsMcY6pLlLkSmrTXgldrqoZ2cezevhxzQCNraSrIu6SW60MAVcFgyjTEXyOyzYwmNEoGgyPtOXp2GEzgtr/fXP+3R6VCup0h1BhKVJmh39Cz3u7V8l6nD/Ki5WWD4UxfDbVUy9QonVPgUAzDGPFEwyqtHJkPBtdIkKAOlt2PxfplX5a3gNChNmqnuKZRgfdbdcvFakD+Q==" Feb 24 19:21:27 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:27+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Feb 24 19:21:27 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:27+01:00" level=info msg="connected to ap-gew4.spotify.com:443" Feb 24 19:21:27 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:27+01:00" level=debug msg="completed keyexchange" Feb 24 19:21:28 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:28+01:00" level=debug msg="completed challenge" Feb 24 19:21:28 minidsp-shd go-librespot[30256]: time="2025-02-24T19:21:28+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:21:28 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:21:28 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:21:28 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 24 19:21:28 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 24 19:21:28 minidsp-shd volumio[635]: info: Discovery: Getting this device information Feb 24 19:21:28 minidsp-shd volumio[635]: info: CoreCommandRouter::volumioGetState Feb 24 19:21:28 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 24 19:21:30 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:30 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:31 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:21:31 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2262. Feb 24 19:21:31 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:21:31 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:21:31 minidsp-shd go-librespot[30272]: Librespot-go daemon starting... Feb 24 19:21:31 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:31+01:00" level=info msg="generated new device id: be244c2b49df616b630aa1077aaad8798e152392" Feb 24 19:21:31 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:31+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:21:31 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:31+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:21:31 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:31+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:21:31 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:31+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:21:31 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:31+01:00" level=debug msg="zeroconf server listening on port 40585" Feb 24 19:21:31 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:31+01:00" level=debug msg="obtained new client token: AABEtRMskhB1MLCPgVu3KFToFkuoPA9iRuaTuomZZwxVkKqYosEoST6N+uWrWEgXNPWE2y6DtHHuXVF8D5rKEIYqspmZZCn1XOEPwroJyFiugcZn2bDIwpnUWFqJWTQloHfP98NXNi2ifAUTXvVRrHg6I07jrnzEKjfdtOxqD0eI4qzt8r4KyMPM9+AHXw22A2YbpHP6XmDgQmllbTw6A41+d4qmpko6AFnJd8Hfrrkny96haLYAmYRPbttcIQ==" Feb 24 19:21:32 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:32+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:21:32 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:32+01:00" level=debug msg="completed keyexchange" Feb 24 19:21:32 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:32+01:00" level=debug msg="completed challenge" Feb 24 19:21:32 minidsp-shd go-librespot[30272]: time="2025-02-24T19:21:32+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:21:32 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:21:32 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:21:33 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:33 minidsp-shd volumio[635]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 19:21:33 minidsp-shd volumio[635]: info: Executing endpoint metavolumio Feb 24 19:21:33 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 24 19:21:35 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:21:35 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2263. Feb 24 19:21:35 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:21:35 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:21:35 minidsp-shd go-librespot[30288]: Librespot-go daemon starting... Feb 24 19:21:35 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:35+01:00" level=info msg="generated new device id: a28681155af89f276440d5c6df5382090021c9e1" Feb 24 19:21:35 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:35+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:21:36 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 19:21:36 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:36+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 19:21:36 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:36+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 19:21:36 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:36+01:00" level=debug msg="zeroconf server listening on port 41575" Feb 24 19:21:36 minidsp-shd volumio[635]: info: Initializing connection to go-librespot Websocket Feb 24 19:21:36 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:36+01:00" level=debug msg="new websocket client" Feb 24 19:21:36 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket established Feb 24 19:21:36 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:36+01:00" level=debug msg="obtained new client token: AAAPbdmr/C6ibgyKvP3iXudn+wgDOgKrPGWWknFcxQCOn0tKquo26rIBGgykitx1OKExQgXgfHYkzvNJ+H5yFk12NvFHd57XWKijCptLTxDVnIZ5hUyQXN8quBQR4n9iaMxaRbiC6t54mYuanaG/OFdfdllE9qeswVtirpA/rK3YjFNsmJE9JBSrvYAo//qMDplai8BKMUDJi55nIST/t34ueGithrWCe01EBwc+22uRoiU6LibEuSp/A44=" Feb 24 19:21:36 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:36+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 19:21:36 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:36+01:00" level=debug msg="completed keyexchange" Feb 24 19:21:36 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:36+01:00" level=debug msg="completed challenge" Feb 24 19:21:36 minidsp-shd go-librespot[30288]: time="2025-02-24T19:21:36+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 19:21:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 19:21:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 19:21:36 minidsp-shd volumio[635]: info: Connection to go-librespot Websocket closed Feb 24 19:21:39 minidsp-shd volumio[635]: Searching all installed plugins Feb 24 19:21:39 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 19:21:39 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: , search Feb 24 19:21:39 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: mpd , search Feb 24 19:21:39 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Feb 24 19:21:39 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Feb 24 19:21:39 minidsp-shd volumio[635]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Feb 24 19:21:39 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: webradio , search Feb 24 19:21:39 minidsp-shd volumio[635]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Feb 24 19:21:39 minidsp-shd volumio[635]: info: [1740421299230] ControllerCalmRadio::searchCategories Feb 24 19:21:39 minidsp-shd volumio[635]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 19:21:39 minidsp-shd volumio[635]: TypeError: Cannot read property 'cats' of undefined Feb 24 19:21:39 minidsp-shd volumio[635]: at ControllerCalmRadio.searchCategories (/data/plugins/music_service/calmradio/index.js:615:42) Feb 24 19:21:39 minidsp-shd volumio[635]: at ControllerCalmRadio.search (/data/plugins/music_service/calmradio/index.js:665:28) Feb 24 19:21:39 minidsp-shd volumio[635]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1077:32) Feb 24 19:21:39 minidsp-shd volumio[635]: at CoreMusicLibrary.searchOnPlugin (/volumio/app/musiclibrary.js:668:44) Feb 24 19:21:39 minidsp-shd volumio[635]: at CoreMusicLibrary.search (/volumio/app/musiclibrary.js:455:27) Feb 24 19:21:39 minidsp-shd volumio[635]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:457:44) Feb 24 19:21:39 minidsp-shd volumio[635]: at Socket.emit (events.js:400:28) Feb 24 19:21:39 minidsp-shd volumio[635]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Feb 24 19:21:39 minidsp-shd volumio[635]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Feb 24 19:21:39 minidsp-shd volumio[635]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 19:21:39 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 19:21:39 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2264. Feb 24 19:21:39 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 19:21:40 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 19:21:40 minidsp-shd go-librespot[30311]: Librespot-go daemon starting... Feb 24 19:21:40 minidsp-shd go-librespot[30311]: time="2025-02-24T19:21:40+01:00" level=info msg="generated new device id: fe87711c0a956270360a0cb7008da41689d64d86" Feb 24 19:21:40 minidsp-shd go-librespot[30311]: time="2025-02-24T19:21:40+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 19:21:40 minidsp-shd sudo[30319]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-24 19:20 Feb 24 19:21:40 minidsp-shd sudo[30319]: 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"