-- Logs begin at Tue 2025-05-27 19:25:39 PDT, end at Sat 2025-06-21 13:37:34 PDT. -- Jun 21 13:36:02 new-pi go-librespot[29874]: time="2025-06-21T13:36:02-07:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Jun 21 13:36:02 new-pi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 13:36:02 new-pi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 13:36:02 new-pi volumio[1019]: (node:1019) UnhandledPromiseRejectionWarning: Error: socket hang up Jun 21 13:36:02 new-pi volumio[1019]: at connResetException (internal/errors.js:607:14) Jun 21 13:36:02 new-pi volumio[1019]: at Socket.socketOnEnd (_http_client.js:493:23) Jun 21 13:36:02 new-pi volumio[1019]: at Socket.emit (events.js:327:22) Jun 21 13:36:02 new-pi volumio[1019]: at endReadableNT (internal/streams/readable.js:1327:12) Jun 21 13:36:02 new-pi volumio[1019]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jun 21 13:36:02 new-pi volumio[1019]: (node:1019) 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: 291) Jun 21 13:36:02 new-pi volumio[1019]: info: Connection to go-librespot Websocket closed Jun 21 13:36:05 new-pi volumio[1019]: info: Initializing connection to go-librespot Websocket Jun 21 13:36:05 new-pi volumio[1019]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 13:36:05 new-pi systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 13:36:05 new-pi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1390. Jun 21 13:36:05 new-pi systemd[1]: Stopped go-librespot Daemon. Jun 21 13:36:05 new-pi systemd[1]: Started go-librespot Daemon. Jun 21 13:36:05 new-pi go-librespot[29976]: Librespot-go daemon starting... Jun 21 13:36:05 new-pi go-librespot[29976]: time="2025-06-21T13:36:05-07:00" level=info msg="generated new device id: 06ef9bc1871f9e8310da31dfd82d13f6d0709693" Jun 21 13:36:05 new-pi go-librespot[29976]: time="2025-06-21T13:36:05-07:00" level=debug msg="stored credentials found for mayurkotlikar" Jun 21 13:36:08 new-pi volumio[1019]: info: Initializing connection to go-librespot Websocket Jun 21 13:36:08 new-pi go-librespot[29976]: time="2025-06-21T13:36:08-07:00" level=debug msg="new websocket client" Jun 21 13:36:08 new-pi volumio[1019]: info: Connection to go-librespot Websocket established Jun 21 13:36:08 new-pi ntpd[804]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Jun 21 13:36:11 new-pi volumio[1019]: info: Getting Spotify volume Jun 21 13:36:11 new-pi volumio[1019]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jun 21 13:36:11 new-pi volumio[1019]: info: CoreCommandRouter::volumioGetState Jun 21 13:36:11 new-pi volumio[1019]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Jun 21 13:36:33 new-pi go-librespot[29976]: time="2025-06-21T13:36:33-07:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Jun 21 13:36:33 new-pi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 13:36:33 new-pi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 13:36:33 new-pi volumio[1019]: (node:1019) UnhandledPromiseRejectionWarning: Error: socket hang up Jun 21 13:36:33 new-pi volumio[1019]: at connResetException (internal/errors.js:607:14) Jun 21 13:36:33 new-pi volumio[1019]: at Socket.socketOnEnd (_http_client.js:493:23) Jun 21 13:36:33 new-pi volumio[1019]: at Socket.emit (events.js:327:22) Jun 21 13:36:33 new-pi volumio[1019]: at endReadableNT (internal/streams/readable.js:1327:12) Jun 21 13:36:33 new-pi volumio[1019]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jun 21 13:36:33 new-pi volumio[1019]: (node:1019) 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: 292) Jun 21 13:36:33 new-pi volumio[1019]: info: Connection to go-librespot Websocket closed Jun 21 13:36:36 new-pi volumio[1019]: info: Initializing connection to go-librespot Websocket Jun 21 13:36:36 new-pi volumio[1019]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 13:36:36 new-pi systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 13:36:36 new-pi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1391. Jun 21 13:36:36 new-pi systemd[1]: Stopped go-librespot Daemon. Jun 21 13:36:36 new-pi systemd[1]: Started go-librespot Daemon. Jun 21 13:36:36 new-pi go-librespot[30040]: Librespot-go daemon starting... Jun 21 13:36:36 new-pi go-librespot[30040]: time="2025-06-21T13:36:36-07:00" level=info msg="generated new device id: 6dbba3bae73b6c3e76280c44c78668a989cde431" Jun 21 13:36:36 new-pi go-librespot[30040]: time="2025-06-21T13:36:36-07:00" level=debug msg="stored credentials found for mayurkotlikar" Jun 21 13:36:36 new-pi ntpd[804]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Jun 21 13:36:39 new-pi volumio[1019]: info: Initializing connection to go-librespot Websocket Jun 21 13:36:39 new-pi volumio[1019]: info: Connection to go-librespot Websocket established Jun 21 13:36:39 new-pi go-librespot[30040]: time="2025-06-21T13:36:39-07:00" level=debug msg="new websocket client" Jun 21 13:36:42 new-pi volumio[1019]: info: Getting Spotify volume Jun 21 13:36:42 new-pi volumio[1019]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jun 21 13:36:42 new-pi volumio[1019]: info: CoreCommandRouter::volumioGetState Jun 21 13:36:42 new-pi volumio[1019]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Jun 21 13:37:04 new-pi go-librespot[30040]: time="2025-06-21T13:37:04-07:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Jun 21 13:37:04 new-pi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 21 13:37:04 new-pi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 21 13:37:04 new-pi volumio[1019]: (node:1019) UnhandledPromiseRejectionWarning: Error: socket hang up Jun 21 13:37:04 new-pi volumio[1019]: at connResetException (internal/errors.js:607:14) Jun 21 13:37:04 new-pi volumio[1019]: at Socket.socketOnEnd (_http_client.js:493:23) Jun 21 13:37:04 new-pi volumio[1019]: at Socket.emit (events.js:327:22) Jun 21 13:37:04 new-pi volumio[1019]: at endReadableNT (internal/streams/readable.js:1327:12) Jun 21 13:37:04 new-pi volumio[1019]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jun 21 13:37:04 new-pi volumio[1019]: (node:1019) 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: 293) Jun 21 13:37:04 new-pi volumio[1019]: info: Connection to go-librespot Websocket closed Jun 21 13:37:04 new-pi ntpd[804]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Jun 21 13:37:07 new-pi volumio[1019]: info: Initializing connection to go-librespot Websocket Jun 21 13:37:07 new-pi volumio[1019]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 21 13:37:07 new-pi systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 21 13:37:07 new-pi systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1392. Jun 21 13:37:07 new-pi systemd[1]: Stopped go-librespot Daemon. Jun 21 13:37:08 new-pi systemd[1]: Started go-librespot Daemon. Jun 21 13:37:08 new-pi go-librespot[30142]: Librespot-go daemon starting... Jun 21 13:37:08 new-pi go-librespot[30142]: time="2025-06-21T13:37:08-07:00" level=info msg="generated new device id: b36241075edf93ce7608a168874dae4c2f2a0f1c" Jun 21 13:37:08 new-pi go-librespot[30142]: time="2025-06-21T13:37:08-07:00" level=debug msg="stored credentials found for mayurkotlikar" Jun 21 13:37:10 new-pi volumio[1019]: info: Initializing connection to go-librespot Websocket Jun 21 13:37:10 new-pi go-librespot[30142]: time="2025-06-21T13:37:10-07:00" level=debug msg="new websocket client" Jun 21 13:37:10 new-pi volumio[1019]: info: Connection to go-librespot Websocket established Jun 21 13:37:13 new-pi volumio[1019]: info: Getting Spotify volume Jun 21 13:37:13 new-pi volumio[1019]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jun 21 13:37:13 new-pi volumio[1019]: info: CoreCommandRouter::volumioGetState Jun 21 13:37:13 new-pi volumio[1019]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Jun 21 13:37:26 new-pi ntpd[804]: Soliciting pool server 209.253.210.115 Jun 21 13:37:27 new-pi ntpd[804]: Soliciting pool server 198.137.202.32 Jun 21 13:37:27 new-pi ntpd[804]: Soliciting pool server 45.83.234.123 Jun 21 13:37:27 new-pi go-librespot[30142]: time="2025-06-21T13:37:27-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 13:37:27 new-pi go-librespot[30142]: time="2025-06-21T13:37:27-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 13:37:27 new-pi go-librespot[30142]: time="2025-06-21T13:37:27-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 13:37:27 new-pi go-librespot[30142]: time="2025-06-21T13:37:27-07:00" level=debug msg="zeroconf server listening on port 40071" Jun 21 13:37:27 new-pi ntpd[804]: Soliciting pool server 141.11.228.173 Jun 21 13:37:27 new-pi ntpd[804]: Soliciting pool server 198.137.202.56 Jun 21 13:37:27 new-pi ntpd[804]: Soliciting pool server 162.159.200.1 Jun 21 13:37:27 new-pi ntpd[804]: Soliciting pool server 45.77.126.122 Jun 21 13:37:27 new-pi go-librespot[30142]: time="2025-06-21T13:37:27-07:00" level=debug msg="obtained new client token: AAAy8YqyPXgZCv7cfPb3Dv1oPC6UKHOOJjbJfyIRRmtnBuvoIgu939OmQlYsiNiNYCUC0HdUkgU3Gcr6Le3TddY6qwAee8WZpGHX6IQH/m26pWAJZ6WOnmPPhN5ycdnX7dI7svEJQCcur/MzAx6h17IrL7KxoBYeP0Osm3X1tLONwb3ysP0wKWgi1LwC2LLfGQcaDlVcfTB/uHQ8xmjXgRqYbNsNjCwbwrUAfri/8fHtDDcxY6/FBM+lC08F" Jun 21 13:37:27 new-pi ntpd[804]: Soliciting pool server 198.46.254.130 Jun 21 13:37:28 new-pi go-librespot[30142]: time="2025-06-21T13:37:28-07:00" level=info msg="connected to ap-guc3.spotify.com:4070" Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 15.204.87.223 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 23.150.40.242 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 72.14.183.39 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 144.202.0.197 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 173.71.68.71 Jun 21 13:37:28 new-pi go-librespot[30142]: time="2025-06-21T13:37:28-07:00" level=debug msg="completed keyexchange" Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 23.150.41.123 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 208.67.75.242 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 198.46.254.130 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 15.204.246.57 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 74.6.168.73 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 50.218.103.254 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 51.81.209.232 Jun 21 13:37:28 new-pi go-librespot[30142]: time="2025-06-21T13:37:28-07:00" level=debug msg="completed challenge" Jun 21 13:37:28 new-pi go-librespot[30142]: time="2025-06-21T13:37:28-07:00" level=debug msg="authenticated as mayurkotlikar" Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 173.255.192.10 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 104.234.61.117 Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 205.233.73.201 Jun 21 13:37:28 new-pi go-librespot[30142]: time="2025-06-21T13:37:28-07:00" level=debug msg="authenticated as mayurkotlikar" Jun 21 13:37:28 new-pi ntpd[804]: Soliciting pool server 99.73.39.214 Jun 21 13:37:29 new-pi go-librespot[30142]: time="2025-06-21T13:37:29-07:00" level=debug msg="dealer connection opened" Jun 21 13:37:29 new-pi go-librespot[30142]: time="2025-06-21T13:37:29-07:00" level=debug msg="initializing zeroconf session, username: mayurkotlikar" Jun 21 13:37:29 new-pi go-librespot[30142]: time="2025-06-21T13:37:29-07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 21 13:37:29 new-pi go-librespot[30142]: time="2025-06-21T13:37:29-07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 21 13:37:29 new-pi go-librespot[30142]: time="2025-06-21T13:37:29-07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 21 13:37:29 new-pi go-librespot[30142]: time="2025-06-21T13:37:29-07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 21 13:37:29 new-pi go-librespot[30142]: time="2025-06-21T13:37:29-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 21 13:37:29 new-pi volumio[1019]: info: Spotify volume: 100 Jun 21 13:37:29 new-pi go-librespot[30142]: time="2025-06-21T13:37:29-07:00" level=debug msg="autoplay enabled: false" Jun 21 13:37:29 new-pi go-librespot[30142]: time="2025-06-21T13:37:29-07:00" level=debug msg="received connection id: MGY4NWYyMDYtMTY3My00NWY4LWE2YWYtZjViMDA1MmNiOGYwK2RlYWxlcit0Y3A6Ly8wYWNiZDg1MC5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArMUY5NjU4Nzk3NUY3QzA0MzhBNTgwNzExQjk1MTcwQUMwNjVFOTAzOTk1REEzRkJCMkVEMDU2Rjc1MkEyRDZERQ==" Jun 21 13:37:29 new-pi go-librespot[30142]: time="2025-06-21T13:37:29-07:00" level=debug msg="put connect state because NEW_DEVICE" Jun 21 13:37:32 new-pi ntpd[804]: 23.186.168.130 local addr 192.168.86.62 -> Jun 21 13:37:34 new-pi volumio[1019]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 21 13:37:34 new-pi volumio[1019]: [t [Error]: A network error (such as timeout, interrupted connection or unreachable host) has occurred.] { Jun 21 13:37:34 new-pi volumio[1019]: code: 'auth/network-request-failed', Jun 21 13:37:34 new-pi volumio[1019]: a: null Jun 21 13:37:34 new-pi volumio[1019]: } Jun 21 13:37:34 new-pi volumio[1019]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 21 13:37:34 new-pi sudo[30213]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-21 13:36 Jun 21 13:37:34 new-pi sudo[30213]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"