-- Logs begin at Sun 2024-08-25 00:46:53 UTC, end at Mon 2024-08-26 22:18:26 UTC. -- Aug 26 22:17:01 volumio go-librespot[19713]: time="2024-08-26T22:17:01Z" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Aug 26 22:17:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 26 22:17:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 26 22:17:01 volumio volumio[976]: (node:976) UnhandledPromiseRejectionWarning: Error: socket hang up Aug 26 22:17:01 volumio volumio[976]: at connResetException (internal/errors.js:607:14) Aug 26 22:17:01 volumio volumio[976]: at Socket.socketOnEnd (_http_client.js:493:23) Aug 26 22:17:01 volumio volumio[976]: at Socket.emit (events.js:327:22) Aug 26 22:17:01 volumio volumio[976]: at endReadableNT (internal/streams/readable.js:1327:12) Aug 26 22:17:01 volumio volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Aug 26 22:17:01 volumio volumio[976]: (node:976) 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: 31344) Aug 26 22:17:01 volumio volumio[976]: info: Connection to go-librespot Websocket closed Aug 26 22:17:04 volumio volumio[976]: info: Initializing connection to go-librespot Websocket Aug 26 22:17:04 volumio volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 26 22:17:04 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 26 22:17:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31288. Aug 26 22:17:04 volumio systemd[1]: Stopped go-librespot Daemon. Aug 26 22:17:04 volumio systemd[1]: Started go-librespot Daemon. Aug 26 22:17:04 volumio go-librespot[19760]: Librespot-go daemon starting... Aug 26 22:17:04 volumio go-librespot[19760]: time="2024-08-26T22:17:04Z" level=info msg="generated new device id: 0183f6484a2fe2a2b91e247cc1844d7260f66ddf" Aug 26 22:17:04 volumio go-librespot[19760]: time="2024-08-26T22:17:04Z" level=debug msg="stored credentials found for jeanleo" Aug 26 22:17:07 volumio volumio[976]: info: Initializing connection to go-librespot Websocket Aug 26 22:17:07 volumio go-librespot[19760]: time="2024-08-26T22:17:07Z" level=debug msg="new websocket client" Aug 26 22:17:07 volumio volumio[976]: info: Connection to go-librespot Websocket established Aug 26 22:17:09 volumio ntpd[686]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Aug 26 22:17:10 volumio volumio[976]: info: Getting Spotify volume Aug 26 22:17:10 volumio volumio[976]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Aug 26 22:17:10 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Aug 26 22:17:10 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 Aug 26 22:17:24 volumio go-librespot[19760]: time="2024-08-26T22:17:24Z" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Aug 26 22:17:24 volumio volumio[976]: (node:976) UnhandledPromiseRejectionWarning: Error: socket hang up Aug 26 22:17:24 volumio volumio[976]: at connResetException (internal/errors.js:607:14) Aug 26 22:17:24 volumio volumio[976]: at Socket.socketOnEnd (_http_client.js:493:23) Aug 26 22:17:24 volumio volumio[976]: at Socket.emit (events.js:327:22) Aug 26 22:17:24 volumio volumio[976]: at endReadableNT (internal/streams/readable.js:1327:12) Aug 26 22:17:24 volumio volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Aug 26 22:17:24 volumio volumio[976]: (node:976) 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: 31345) Aug 26 22:17:24 volumio volumio[976]: info: Connection to go-librespot Websocket closed Aug 26 22:17:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 26 22:17:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 26 22:17:27 volumio volumio[976]: info: Initializing connection to go-librespot Websocket Aug 26 22:17:27 volumio volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 26 22:17:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 26 22:17:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31289. Aug 26 22:17:27 volumio systemd[1]: Stopped go-librespot Daemon. Aug 26 22:17:27 volumio systemd[1]: Started go-librespot Daemon. Aug 26 22:17:27 volumio go-librespot[19770]: Librespot-go daemon starting... Aug 26 22:17:27 volumio go-librespot[19770]: time="2024-08-26T22:17:27Z" level=info msg="generated new device id: 09ebd8c158539fd75c33e487046e4d27a44cb9ea" Aug 26 22:17:27 volumio go-librespot[19770]: time="2024-08-26T22:17:27Z" level=debug msg="stored credentials found for jeanleo" Aug 26 22:17:29 volumio ntpd[686]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Aug 26 22:17:30 volumio volumio[976]: info: Initializing connection to go-librespot Websocket Aug 26 22:17:30 volumio volumio[976]: info: Connection to go-librespot Websocket established Aug 26 22:17:30 volumio go-librespot[19770]: time="2024-08-26T22:17:30Z" level=debug msg="new websocket client" Aug 26 22:17:33 volumio volumio[976]: info: Getting Spotify volume Aug 26 22:17:33 volumio volumio[976]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Aug 26 22:17:33 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Aug 26 22:17:33 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 Aug 26 22:17:47 volumio go-librespot[19770]: time="2024-08-26T22:17:47Z" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Aug 26 22:17:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 26 22:17:47 volumio volumio[976]: (node:976) UnhandledPromiseRejectionWarning: Error: socket hang up Aug 26 22:17:47 volumio volumio[976]: at connResetException (internal/errors.js:607:14) Aug 26 22:17:47 volumio volumio[976]: at Socket.socketOnEnd (_http_client.js:493:23) Aug 26 22:17:47 volumio volumio[976]: at Socket.emit (events.js:327:22) Aug 26 22:17:47 volumio volumio[976]: at endReadableNT (internal/streams/readable.js:1327:12) Aug 26 22:17:47 volumio volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Aug 26 22:17:47 volumio volumio[976]: (node:976) 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: 31346) Aug 26 22:17:47 volumio volumio[976]: info: Connection to go-librespot Websocket closed Aug 26 22:17:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 26 22:17:49 volumio ntpd[686]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Aug 26 22:17:50 volumio volumio[976]: info: Initializing connection to go-librespot Websocket Aug 26 22:17:50 volumio volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 26 22:17:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 26 22:17:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31290. Aug 26 22:17:51 volumio systemd[1]: Stopped go-librespot Daemon. Aug 26 22:17:51 volumio systemd[1]: Started go-librespot Daemon. Aug 26 22:17:51 volumio go-librespot[19779]: Librespot-go daemon starting... Aug 26 22:17:51 volumio go-librespot[19779]: time="2024-08-26T22:17:51Z" level=info msg="generated new device id: acf4609b2a21e6f41d3b03a7ed0ba065ef2e5c98" Aug 26 22:17:51 volumio go-librespot[19779]: time="2024-08-26T22:17:51Z" level=debug msg="stored credentials found for jeanleo" Aug 26 22:17:53 volumio volumio[976]: info: Initializing connection to go-librespot Websocket Aug 26 22:17:53 volumio go-librespot[19779]: time="2024-08-26T22:17:53Z" level=debug msg="new websocket client" Aug 26 22:17:53 volumio volumio[976]: info: Connection to go-librespot Websocket established Aug 26 22:17:56 volumio volumio[976]: info: Getting Spotify volume Aug 26 22:17:56 volumio volumio[976]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Aug 26 22:17:56 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Aug 26 22:17:56 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 Aug 26 22:18:05 volumio wpa_supplicant[818]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="slagtand" Aug 26 22:18:05 volumio wpa_supplicant[818]: wlan0: Failed to initiate sched scan Aug 26 22:18:09 volumio ntpd[686]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Aug 26 22:18:10 volumio wpa_supplicant[818]: wlan0: Trying to associate with SSID 'slagtand' Aug 26 22:18:11 volumio go-librespot[19779]: time="2024-08-26T22:18:11Z" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Aug 26 22:18:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 26 22:18:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 26 22:18:11 volumio volumio[976]: (node:976) UnhandledPromiseRejectionWarning: Error: socket hang up Aug 26 22:18:11 volumio volumio[976]: at connResetException (internal/errors.js:607:14) Aug 26 22:18:11 volumio volumio[976]: at Socket.socketOnEnd (_http_client.js:493:23) Aug 26 22:18:11 volumio volumio[976]: at Socket.emit (events.js:327:22) Aug 26 22:18:11 volumio volumio[976]: at endReadableNT (internal/streams/readable.js:1327:12) Aug 26 22:18:11 volumio volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Aug 26 22:18:11 volumio volumio[976]: (node:976) 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: 31347) Aug 26 22:18:11 volumio volumio[976]: info: Connection to go-librespot Websocket closed Aug 26 22:18:11 volumio dhcpcd[864]: wlan0: carrier acquired Aug 26 22:18:11 volumio wpa_supplicant[818]: wlan0: Associated with 04:42:1a:a4:bd:80 Aug 26 22:18:11 volumio wpa_supplicant[818]: wlan0: CTRL-EVENT-CONNECTED - Connection to 04:42:1a:a4:bd:80 completed [id=0 id_str=] Aug 26 22:18:11 volumio wpa_supplicant[818]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Aug 26 22:18:11 volumio dhcpcd[864]: wlan0: IAID eb:55:c8:05 Aug 26 22:18:11 volumio dhcpcd[864]: wlan0: carrier lost Aug 26 22:18:11 volumio dhcpcd[864]: wlan0: carrier acquired Aug 26 22:18:11 volumio dhcpcd[864]: wlan0: IAID eb:55:c8:05 Aug 26 22:18:11 volumio dhcpcd[864]: wlan0: rebinding lease of 192.168.3.244 Aug 26 22:18:11 volumio dhcpcd[864]: wlan0: soliciting an IPv6 router Aug 26 22:18:14 volumio volumio[976]: info: Initializing connection to go-librespot Websocket Aug 26 22:18:14 volumio volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 26 22:18:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 26 22:18:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31291. Aug 26 22:18:14 volumio systemd[1]: Stopped go-librespot Daemon. Aug 26 22:18:14 volumio systemd[1]: Started go-librespot Daemon. Aug 26 22:18:14 volumio go-librespot[19838]: Librespot-go daemon starting... Aug 26 22:18:14 volumio go-librespot[19838]: time="2024-08-26T22:18:14Z" level=info msg="generated new device id: 592a86e3226372e569f334af7275cf3313b6083b" Aug 26 22:18:14 volumio go-librespot[19838]: time="2024-08-26T22:18:14Z" level=debug msg="stored credentials found for jeanleo" Aug 26 22:18:15 volumio dhcpcd[864]: wlan0: probing address 192.168.3.244/24 Aug 26 22:18:17 volumio volumio[976]: info: Initializing connection to go-librespot Websocket Aug 26 22:18:20 volumio dhcpcd[864]: wlan0: leased 192.168.3.244 for 86400 seconds Aug 26 22:18:20 volumio avahi-daemon[529]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.3.244. Aug 26 22:18:20 volumio avahi-daemon[529]: New relevant interface wlan0.IPv4 for mDNS. Aug 26 22:18:20 volumio avahi-daemon[529]: Registering new address record for 192.168.3.244 on wlan0.IPv4. Aug 26 22:18:20 volumio dhcpcd[864]: wlan0: adding route to 192.168.3.0/24 Aug 26 22:18:20 volumio dhcpcd[864]: wlan0: adding default route via 192.168.3.1 Aug 26 22:18:20 volumio dhcpcd[864]: eth0: deleting default route Aug 26 22:18:20 volumio dhcpcd[769]: eth0: pid 864 deleted default route Aug 26 22:18:20 volumio go-librespot[19838]: time="2024-08-26T22:18:20Z" level=debug msg="new websocket client" Aug 26 22:18:20 volumio volumio[976]: info: Connection to go-librespot Websocket established Aug 26 22:18:22 volumio ntpd[686]: Listen normally on 1909 wlan0 192.168.3.244:123 Aug 26 22:18:22 volumio ntpd[686]: 193.123.56.220 local addr 169.254.154.120 -> 192.168.3.244 Aug 26 22:18:22 volumio ntpd[686]: 195.123.221.21 local addr 169.254.154.120 -> 192.168.3.244 Aug 26 22:18:22 volumio ntpd[686]: 185.224.145.68 local addr 169.254.154.120 -> 192.168.3.244 Aug 26 22:18:22 volumio ntpd[686]: 185.45.112.121 local addr 169.254.154.120 -> 192.168.3.244 Aug 26 22:18:22 volumio ntpd[686]: 167.99.42.106 local addr 169.254.154.120 -> 192.168.3.244 Aug 26 22:18:22 volumio ntpd[686]: 94.198.159.16 local addr 169.254.154.120 -> 192.168.3.244 Aug 26 22:18:22 volumio ntpd[686]: new interface(s) found: waking up resolver Aug 26 22:18:23 volumio volumio[976]: info: Getting Spotify volume Aug 26 22:18:26 volumio volumio[976]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 26 22:18:26 volumio volumio[976]: [t [Error]: A network error (such as timeout, interrupted connection or unreachable host) has occurred.] { Aug 26 22:18:26 volumio volumio[976]: code: 'auth/network-request-failed', Aug 26 22:18:26 volumio volumio[976]: a: null Aug 26 22:18:26 volumio volumio[976]: } Aug 26 22:18:26 volumio volumio[976]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 26 22:18:26 volumio sudo[19878]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-26 22:17 Aug 26 22:18:26 volumio sudo[19878]: 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="9552505bba4239c163ac9ee7b0b87a56e0dd0574" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="3d3fc502273a5c173ba19f72c1a952bdb2bdd3b0" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 Feb 2024 06:28:23 PM CET" VOLUMIO_VERSION="3.616" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b343c71baf05cbc21bf1a530c8e51fc1"