-- Logs begin at Sat 2025-07-05 11:54:28 CEST, end at Sat 2025-07-05 14:06:16 CEST. -- Jul 05 14:05:00 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:00 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:05 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:05 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:10 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:10 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:12 volumio ntpd[594]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Jul 05 14:05:12 volumio go-librespot[24723]: time="2025-07-05T14:05:12+02: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" Jul 05 14:05:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 05 14:05:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 05 14:05:12 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 05 14:05:12 volumio volumio[858]: at connResetException (internal/errors.js:607:14) Jul 05 14:05:12 volumio volumio[858]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 05 14:05:12 volumio volumio[858]: at Socket.emit (events.js:327:22) Jul 05 14:05:12 volumio volumio[858]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 05 14:05:12 volumio volumio[858]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 05 14:05:12 volumio volumio[858]: (node:858) 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: 2386) Jul 05 14:05:12 volumio volumio[858]: info: Connection to go-librespot Websocket closed Jul 05 14:05:14 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:14 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:14 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jul 05 14:05:15 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:15 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:15 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Jul 05 14:05:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 05 14:05:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4958. Jul 05 14:05:15 volumio systemd[1]: Stopped go-librespot Daemon. Jul 05 14:05:15 volumio systemd[1]: Started go-librespot Daemon. Jul 05 14:05:15 volumio go-librespot[24770]: go-librespot daemon starting... Jul 05 14:05:16 volumio go-librespot[24770]: time="2025-07-05T14:05:16+02:00" level=info msg="running go-librespot 0.2.0" Jul 05 14:05:16 volumio go-librespot[24770]: time="2025-07-05T14:05:16+02:00" level=debug msg="app state loaded" Jul 05 14:05:16 volumio go-librespot[24770]: time="2025-07-05T14:05:16+02:00" level=debug msg="stored credentials not found" Jul 05 14:05:16 volumio go-librespot[24770]: time="2025-07-05T14:05:16+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 05 14:05:20 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:20 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:24 volumio volumio[858]: info: Discovery: adding dd936ff3-7117-4e93-9a41-d60f6a2507dc Jul 05 14:05:24 volumio volumio[858]: info: Discovery: Found device Marshall Jul 05 14:05:24 volumio volumio[858]: info: Discovery: Connecting to remote: 192.168.132.53 Jul 05 14:05:24 volumio go-librespot[24770]: time="2025-07-05T14:05:24+02:00" level=debug msg="new websocket client" Jul 05 14:05:24 volumio volumio[858]: info: Connection to go-librespot Websocket established Jul 05 14:05:24 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:24 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:24 volumio volumio[858]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Jul 05 14:05:25 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:25 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:27 volumio volumio[858]: info: Getting Spotify volume Jul 05 14:05:27 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jul 05 14:05:27 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:27 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:28 volumio volumio[858]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Jul 05 14:05:30 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:30 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:35 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:35 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:35 volumio ntpd[594]: Soliciting pool server 2001:718:801:230::8c Jul 05 14:05:36 volumio go-librespot[24770]: time="2025-07-05T14:05:36+02: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" Jul 05 14:05:36 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 05 14:05:36 volumio volumio[858]: at connResetException (internal/errors.js:607:14) Jul 05 14:05:36 volumio volumio[858]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 05 14:05:36 volumio volumio[858]: at Socket.emit (events.js:327:22) Jul 05 14:05:36 volumio volumio[858]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 05 14:05:36 volumio volumio[858]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 05 14:05:36 volumio volumio[858]: (node:858) 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: 2389) Jul 05 14:05:36 volumio volumio[858]: info: Connection to go-librespot Websocket closed Jul 05 14:05:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 05 14:05:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 05 14:05:38 volumio ntpd[594]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Jul 05 14:05:39 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Jul 05 14:05:39 volumio volumio[858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 05 14:05:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 05 14:05:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4959. Jul 05 14:05:39 volumio systemd[1]: Stopped go-librespot Daemon. Jul 05 14:05:39 volumio systemd[1]: Started go-librespot Daemon. Jul 05 14:05:39 volumio go-librespot[24815]: go-librespot daemon starting... Jul 05 14:05:39 volumio go-librespot[24815]: time="2025-07-05T14:05:39+02:00" level=info msg="running go-librespot 0.2.0" Jul 05 14:05:39 volumio go-librespot[24815]: time="2025-07-05T14:05:39+02:00" level=debug msg="app state loaded" Jul 05 14:05:39 volumio go-librespot[24815]: time="2025-07-05T14:05:39+02:00" level=debug msg="stored credentials not found" Jul 05 14:05:39 volumio go-librespot[24815]: time="2025-07-05T14:05:39+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 05 14:05:40 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:40 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:42 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Jul 05 14:05:42 volumio volumio[858]: info: Connection to go-librespot Websocket established Jul 05 14:05:42 volumio go-librespot[24815]: time="2025-07-05T14:05:42+02:00" level=debug msg="new websocket client" Jul 05 14:05:45 volumio volumio[858]: info: Getting Spotify volume Jul 05 14:05:45 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jul 05 14:05:45 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:45 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:45 volumio volumio[858]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Jul 05 14:05:45 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:45 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:50 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:50 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:55 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:05:55 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:05:58 volumio ntpd[594]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Jul 05 14:05:59 volumio go-librespot[24815]: time="2025-07-05T14:05:59+02: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" Jul 05 14:05:59 volumio volumio[858]: (node:858) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 05 14:05:59 volumio volumio[858]: at connResetException (internal/errors.js:607:14) Jul 05 14:05:59 volumio volumio[858]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 05 14:05:59 volumio volumio[858]: at Socket.emit (events.js:327:22) Jul 05 14:05:59 volumio volumio[858]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 05 14:05:59 volumio volumio[858]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 05 14:05:59 volumio volumio[858]: (node:858) 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: 2391) Jul 05 14:05:59 volumio volumio[858]: info: Connection to go-librespot Websocket closed Jul 05 14:05:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 05 14:05:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 05 14:06:00 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:06:00 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:06:02 volumio volumio[858]: info: Initializing connection to go-librespot Websocket Jul 05 14:06:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 05 14:06:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4960. Jul 05 14:06:02 volumio systemd[1]: Stopped go-librespot Daemon. Jul 05 14:06:02 volumio systemd[1]: Started go-librespot Daemon. Jul 05 14:06:02 volumio go-librespot[24900]: go-librespot daemon starting... Jul 05 14:06:02 volumio go-librespot[24900]: time="2025-07-05T14:06:02+02:00" level=info msg="running go-librespot 0.2.0" Jul 05 14:06:02 volumio go-librespot[24900]: time="2025-07-05T14:06:02+02:00" level=debug msg="app state loaded" Jul 05 14:06:02 volumio go-librespot[24900]: time="2025-07-05T14:06:02+02:00" level=debug msg="stored credentials not found" Jul 05 14:06:02 volumio go-librespot[24900]: time="2025-07-05T14:06:02+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 05 14:06:04 volumio dhcpcd[799]: wlan0: offered 192.168.132.54 from 192.168.132.2 Jul 05 14:06:04 volumio dhcpcd[799]: wlan0: probing address 192.168.132.54/24 Jul 05 14:06:05 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:06:05 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:06:08 volumio dhcpcd[799]: wlan0: leased 192.168.132.54 for 86400 seconds Jul 05 14:06:08 volumio avahi-daemon[418]: Registering new address record for 192.168.132.54 on wlan0.IPv4. Jul 05 14:06:08 volumio dhcpcd[799]: wlan0: adding route to 192.168.132.0/24 Jul 05 14:06:08 volumio dhcpcd[799]: wlan0: changing default route via 192.168.132.1 Jul 05 14:06:08 volumio avahi-daemon[418]: Withdrawing address record for 169.254.203.182 on wlan0. Jul 05 14:06:08 volumio avahi-daemon[418]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 169.254.203.182. Jul 05 14:06:08 volumio dhcpcd[799]: wlan0: deleting route to 169.254.0.0/16 Jul 05 14:06:08 volumio avahi-daemon[418]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.132.54. Jul 05 14:06:08 volumio dhcpcd[799]: wlan0: pid 799 deleted default route via 192.168.132.1 Jul 05 14:06:09 volumio go-librespot[24900]: time="2025-07-05T14:06:09+02:00" level=debug msg="new websocket client" Jul 05 14:06:09 volumio volumio[858]: info: Connection to go-librespot Websocket established Jul 05 14:06:10 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:06:10 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:06:10 volumio volumio[858]: verbose: New Socket.io Connection to 192.168.132.54:3000 from 192.168.132.53 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jul 05 14:06:10 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Jul 05 14:06:10 volumio ntpd[594]: Listen normally on 10 wlan0 192.168.132.54:123 Jul 05 14:06:10 volumio ntpd[594]: Deleting interface #9 wlan0, 169.254.203.182#123, interface stats: received=0, sent=14, dropped=0, active_time=125 secs Jul 05 14:06:10 volumio ntpd[594]: 162.159.200.123 local addr 169.254.203.182 -> Jul 05 14:06:10 volumio ntpd[594]: 78.108.102.237 local addr 169.254.203.182 -> Jul 05 14:06:10 volumio ntpd[594]: 194.182.77.109 local addr 169.254.203.182 -> Jul 05 14:06:10 volumio ntpd[594]: 185.47.221.82 local addr 169.254.203.182 -> Jul 05 14:06:10 volumio ntpd[594]: 81.0.208.219 local addr 169.254.203.182 -> Jul 05 14:06:10 volumio ntpd[594]: 89.203.251.72 local addr 169.254.203.182 -> Jul 05 14:06:10 volumio ntpd[594]: 78.80.37.86 local addr 169.254.203.182 -> Jul 05 14:06:10 volumio ntpd[594]: new interface(s) found: waking up resolver Jul 05 14:06:10 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:06:10 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:06:12 volumio volumio[858]: info: Getting Spotify volume Jul 05 14:06:12 volumio volumio[858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jul 05 14:06:12 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Jul 05 14:06:12 volumio volumio[858]: info: CorePlayQueue::getTrack 0 Jul 05 14:06:12 volumio volumio[858]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Jul 05 14:06:13 volumio volumio[858]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 05 14:06:13 volumio volumio[858]: [t [Error]: A network error (such as timeout, interrupted connection or unreachable host) has occurred.] { Jul 05 14:06:13 volumio volumio[858]: code: 'auth/network-request-failed', Jul 05 14:06:13 volumio volumio[858]: a: null Jul 05 14:06:13 volumio volumio[858]: } Jul 05 14:06:13 volumio volumio[858]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 05 14:06:13 volumio go-librespot[24900]: time="2025-07-05T14:06:13+02: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]" Jul 05 14:06:13 volumio go-librespot[24900]: time="2025-07-05T14:06:13+02: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]" Jul 05 14:06:13 volumio go-librespot[24900]: time="2025-07-05T14:06:13+02: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]" Jul 05 14:06:13 volumio go-librespot[24900]: time="2025-07-05T14:06:13+02:00" level=info msg="zeroconf server listening on port 41031" Jul 05 14:06:13 volumio ntpd[594]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Jul 05 14:06:13 volumio go-librespot[24900]: time="2025-07-05T14:06:13+02:00" level=debug msg="obtained new client token: AAB4I0M/HXoqgooPCXNexg4W/1IUidZ+/vpE82MTR39o2WwkRsxXgggYo+xVHa1LreZT5rDB/EWOyaBpuXjc11MwRlz7CArIyTC5F5SJKzlMJ93AyHCcp6NN2BVp1m7TsuKSGzjO4wLBLph1WvtNc6+2hF3Nb8Ndp8ALtta//7udgN+QnlKnGDXCxjES9Z83rFufEhBoxl4x44FPVLpXwQdT/J2r5Hct6v5RqHidEomUSTzXNUqo9lcB2Q==" Jul 05 14:06:14 volumio go-librespot[24900]: time="2025-07-05T14:06:14+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 05 14:06:14 volumio go-librespot[24900]: time="2025-07-05T14:06:14+02:00" level=debug msg="completed keyexchange" Jul 05 14:06:14 volumio go-librespot[24900]: time="2025-07-05T14:06:14+02:00" level=debug msg="completed challenge" Jul 05 14:06:14 volumio go-librespot[24900]: time="2025-07-05T14:06:14+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jul 05 14:06:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 05 14:06:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 05 14:06:16 volumio sudo[24992]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-05 14:05 Jul 05 14:06:16 volumio sudo[24992]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 02 Jul 2025 04:07:25 PM CEST" VOLUMIO_VERSION="3.819" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3b9115b1943141a9d7186aa434f8f3c2"