-- Logs begin at Sun 2024-07-21 20:45:49 CEST, end at Mon 2024-07-22 02:34:29 CEST. -- Jul 22 02:33:01 rpi-volumio-te volumio[846]: info: Initializing connection to go-librespot Websocket Jul 22 02:33:01 rpi-volumio-te volumio[846]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 22 02:33:01 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 22 02:33:01 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 152928. Jul 22 02:33:01 rpi-volumio-te systemd[1]: Stopped go-librespot Daemon. Jul 22 02:33:01 rpi-volumio-te systemd[1]: Started go-librespot Daemon. Jul 22 02:33:01 rpi-volumio-te go-librespot[7445]: Librespot-go daemon starting... Jul 22 02:33:01 rpi-volumio-te go-librespot[7445]: time="2024-07-22T02:33:01+02:00" level=info msg="generated new device id: a9be62af9fb126a4c3487885a4a77a740e5e7619" Jul 22 02:33:01 rpi-volumio-te go-librespot[7445]: time="2024-07-22T02:33:01+02:00" level=debug msg="stored credentials found for tenex24" Jul 22 02:33:04 rpi-volumio-te volumio[846]: info: Initializing connection to go-librespot Websocket Jul 22 02:33:04 rpi-volumio-te go-librespot[7445]: time="2024-07-22T02:33:04+02:00" level=debug msg="new websocket client" Jul 22 02:33:04 rpi-volumio-te volumio[846]: info: Connection to go-librespot Websocket established Jul 22 02:33:07 rpi-volumio-te volumio[846]: info: Getting Spotify volume Jul 22 02:33:07 rpi-volumio-te volumio[846]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Jul 22 02:33:07 rpi-volumio-te volumio[846]: info: CoreCommandRouter::volumioGetState Jul 22 02:33:07 rpi-volumio-te volumio[846]: info: CorePlayQueue::getTrack 0 Jul 22 02:33:07 rpi-volumio-te volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Jul 22 02:33:11 rpi-volumio-te go-librespot[7445]: time="2024-07-22T02:33:11+02:00" 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\": net/http: TLS handshake timeout" Jul 22 02:33:11 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 22 02:33:11 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 22 02:33:11 rpi-volumio-te volumio[846]: (node:846) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 22 02:33:11 rpi-volumio-te volumio[846]: at connResetException (internal/errors.js:607:14) Jul 22 02:33:11 rpi-volumio-te volumio[846]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 22 02:33:11 rpi-volumio-te volumio[846]: at Socket.emit (events.js:327:22) Jul 22 02:33:11 rpi-volumio-te volumio[846]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 22 02:33:11 rpi-volumio-te volumio[846]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 22 02:33:11 rpi-volumio-te volumio[846]: (node:846) 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: 1238) Jul 22 02:33:11 rpi-volumio-te volumio[846]: info: Connection to go-librespot Websocket closed Jul 22 02:33:14 rpi-volumio-te volumio[846]: info: Initializing connection to go-librespot Websocket Jul 22 02:33:14 rpi-volumio-te volumio[846]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 22 02:33:15 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 22 02:33:15 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 152929. Jul 22 02:33:15 rpi-volumio-te systemd[1]: Stopped go-librespot Daemon. Jul 22 02:33:15 rpi-volumio-te systemd[1]: Started go-librespot Daemon. Jul 22 02:33:15 rpi-volumio-te go-librespot[7494]: Librespot-go daemon starting... Jul 22 02:33:15 rpi-volumio-te go-librespot[7494]: time="2024-07-22T02:33:15+02:00" level=info msg="generated new device id: 06a5132f78d7ec8648b1ab51bc4596ffdc60e444" Jul 22 02:33:15 rpi-volumio-te go-librespot[7494]: time="2024-07-22T02:33:15+02:00" level=debug msg="stored credentials found for tenex24" Jul 22 02:33:17 rpi-volumio-te volumio[846]: info: Initializing connection to go-librespot Websocket Jul 22 02:33:17 rpi-volumio-te go-librespot[7494]: time="2024-07-22T02:33:17+02:00" level=debug msg="new websocket client" Jul 22 02:33:17 rpi-volumio-te volumio[846]: info: Connection to go-librespot Websocket established Jul 22 02:33:20 rpi-volumio-te volumio[846]: info: Getting Spotify volume Jul 22 02:33:20 rpi-volumio-te volumio[846]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Jul 22 02:33:21 rpi-volumio-te volumio[846]: info: CoreCommandRouter::volumioGetState Jul 22 02:33:21 rpi-volumio-te volumio[846]: info: CorePlayQueue::getTrack 0 Jul 22 02:33:21 rpi-volumio-te volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Jul 22 02:33:28 rpi-volumio-te go-librespot[7494]: time="2024-07-22T02:33:28+02:00" 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\": net/http: TLS handshake timeout" Jul 22 02:33:28 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 22 02:33:28 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 22 02:33:28 rpi-volumio-te volumio[846]: (node:846) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 22 02:33:28 rpi-volumio-te volumio[846]: at connResetException (internal/errors.js:607:14) Jul 22 02:33:28 rpi-volumio-te volumio[846]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 22 02:33:28 rpi-volumio-te volumio[846]: at Socket.emit (events.js:327:22) Jul 22 02:33:28 rpi-volumio-te volumio[846]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 22 02:33:28 rpi-volumio-te volumio[846]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 22 02:33:28 rpi-volumio-te volumio[846]: (node:846) 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: 1240) Jul 22 02:33:28 rpi-volumio-te volumio[846]: info: Connection to go-librespot Websocket closed Jul 22 02:33:31 rpi-volumio-te volumio[846]: info: Initializing connection to go-librespot Websocket Jul 22 02:33:31 rpi-volumio-te volumio[846]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 22 02:33:31 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 22 02:33:31 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 152930. Jul 22 02:33:31 rpi-volumio-te systemd[1]: Stopped go-librespot Daemon. Jul 22 02:33:31 rpi-volumio-te systemd[1]: Started go-librespot Daemon. Jul 22 02:33:31 rpi-volumio-te go-librespot[7501]: Librespot-go daemon starting... Jul 22 02:33:31 rpi-volumio-te go-librespot[7501]: time="2024-07-22T02:33:31+02:00" level=info msg="generated new device id: 73b28d7e62004d57862c982dc085ce95041fb419" Jul 22 02:33:31 rpi-volumio-te go-librespot[7501]: time="2024-07-22T02:33:31+02:00" level=debug msg="stored credentials found for tenex24" Jul 22 02:33:34 rpi-volumio-te volumio[846]: info: Initializing connection to go-librespot Websocket Jul 22 02:33:34 rpi-volumio-te go-librespot[7501]: time="2024-07-22T02:33:34+02:00" level=debug msg="new websocket client" Jul 22 02:33:34 rpi-volumio-te volumio[846]: info: Connection to go-librespot Websocket established Jul 22 02:33:37 rpi-volumio-te volumio[846]: info: Getting Spotify volume Jul 22 02:33:37 rpi-volumio-te volumio[846]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Jul 22 02:33:37 rpi-volumio-te volumio[846]: info: CoreCommandRouter::volumioGetState Jul 22 02:33:37 rpi-volumio-te volumio[846]: info: CorePlayQueue::getTrack 0 Jul 22 02:33:37 rpi-volumio-te volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Jul 22 02:33:41 rpi-volumio-te go-librespot[7501]: time="2024-07-22T02:33:41+02:00" 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\": unexpected EOF" Jul 22 02:33:41 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 22 02:33:41 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 22 02:33:41 rpi-volumio-te volumio[846]: (node:846) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 22 02:33:41 rpi-volumio-te volumio[846]: at connResetException (internal/errors.js:607:14) Jul 22 02:33:41 rpi-volumio-te volumio[846]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 22 02:33:41 rpi-volumio-te volumio[846]: at Socket.emit (events.js:327:22) Jul 22 02:33:41 rpi-volumio-te volumio[846]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 22 02:33:41 rpi-volumio-te volumio[846]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 22 02:33:41 rpi-volumio-te volumio[846]: (node:846) 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: 1241) Jul 22 02:33:41 rpi-volumio-te volumio[846]: info: Connection to go-librespot Websocket closed Jul 22 02:33:44 rpi-volumio-te volumio[846]: info: Initializing connection to go-librespot Websocket Jul 22 02:33:44 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 22 02:33:44 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 152931. Jul 22 02:33:44 rpi-volumio-te volumio[846]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 22 02:33:44 rpi-volumio-te systemd[1]: Stopped go-librespot Daemon. Jul 22 02:33:44 rpi-volumio-te systemd[1]: Started go-librespot Daemon. Jul 22 02:33:44 rpi-volumio-te go-librespot[7510]: Librespot-go daemon starting... Jul 22 02:33:44 rpi-volumio-te go-librespot[7510]: time="2024-07-22T02:33:44+02:00" level=info msg="generated new device id: 38a88578b83207bcded3f70484fe86b6a0759e06" Jul 22 02:33:44 rpi-volumio-te go-librespot[7510]: time="2024-07-22T02:33:44+02:00" level=debug msg="stored credentials found for tenex24" Jul 22 02:33:45 rpi-volumio-te volumio[846]: info: Getting Push Notification urls Jul 22 02:33:47 rpi-volumio-te volumio[846]: info: Initializing connection to go-librespot Websocket Jul 22 02:33:47 rpi-volumio-te go-librespot[7510]: time="2024-07-22T02:33:47+02:00" level=debug msg="new websocket client" Jul 22 02:33:47 rpi-volumio-te volumio[846]: info: Connection to go-librespot Websocket established Jul 22 02:33:50 rpi-volumio-te volumio[846]: info: Getting Spotify volume Jul 22 02:33:50 rpi-volumio-te volumio[846]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Jul 22 02:33:50 rpi-volumio-te volumio[846]: info: CoreCommandRouter::volumioGetState Jul 22 02:33:50 rpi-volumio-te volumio[846]: info: CorePlayQueue::getTrack 0 Jul 22 02:33:50 rpi-volumio-te volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Jul 22 02:33:51 rpi-volumio-te go-librespot[7510]: time="2024-07-22T02:33:51+02:00" level=debug msg="obtained new client token: AAAkZoJO4AhWjP+kuNXg6J9iRVDOjOPBZ+YN4Dlcl4bQ72CGdF+sKVQgHz4tQDpjyYBFk+MkU1zMj1s3p7zmhbdGXY764PlZcQkn6X4UQJCHR3IpPQMAqB60rNkflm3oygImL8hB1LNampThUs1DlfPA1gAPQuZIWKvxgNm40hN6uLJnyWqwEIM4ds/V6nDCvOsqmse3IpPIzLKA5ziyhB9AWzhNq8gIQSL3pf3qBMP+yqdQk/AvpOvEwA4=" Jul 22 02:33:53 rpi-volumio-te go-librespot[7510]: time="2024-07-22T02:33:53+02: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]" Jul 22 02:33:53 rpi-volumio-te go-librespot[7510]: time="2024-07-22T02:33:53+02:00" level=debug msg="completed keyexchange" Jul 22 02:33:53 rpi-volumio-te go-librespot[7510]: time="2024-07-22T02:33:53+02:00" level=debug msg="completed challenge" Jul 22 02:34:00 rpi-volumio-te go-librespot[7510]: time="2024-07-22T02:34:00+02:00" level=debug msg="authenticated as tenex24" Jul 22 02:34:16 rpi-volumio-te go-librespot[7510]: time="2024-07-22T02:34:16+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed requesting login5 endpoint: failed requesting login5: Post \"https://login5.spotify.com/v3/login\": net/http: TLS handshake timeout" Jul 22 02:34:16 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 22 02:34:16 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 22 02:34:16 rpi-volumio-te volumio[846]: (node:846) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 22 02:34:16 rpi-volumio-te volumio[846]: at connResetException (internal/errors.js:607:14) Jul 22 02:34:16 rpi-volumio-te volumio[846]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 22 02:34:16 rpi-volumio-te volumio[846]: at Socket.emit (events.js:327:22) Jul 22 02:34:16 rpi-volumio-te volumio[846]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 22 02:34:16 rpi-volumio-te volumio[846]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 22 02:34:16 rpi-volumio-te volumio[846]: (node:846) 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: 1243) Jul 22 02:34:16 rpi-volumio-te volumio[846]: info: Connection to go-librespot Websocket closed Jul 22 02:34:16 rpi-volumio-te volumio[846]: info: Adding Push Notification url Jul 22 02:34:19 rpi-volumio-te volumio[846]: info: Initializing connection to go-librespot Websocket Jul 22 02:34:19 rpi-volumio-te volumio[846]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 22 02:34:19 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 22 02:34:19 rpi-volumio-te systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 152932. Jul 22 02:34:19 rpi-volumio-te systemd[1]: Stopped go-librespot Daemon. Jul 22 02:34:19 rpi-volumio-te systemd[1]: Started go-librespot Daemon. Jul 22 02:34:19 rpi-volumio-te go-librespot[7559]: Librespot-go daemon starting... Jul 22 02:34:19 rpi-volumio-te go-librespot[7559]: time="2024-07-22T02:34:19+02:00" level=info msg="generated new device id: 06d2bd1d5dba055a76a71a0f349b8d2a4dfc3faa" Jul 22 02:34:19 rpi-volumio-te go-librespot[7559]: time="2024-07-22T02:34:19+02:00" level=debug msg="stored credentials found for tenex24" Jul 22 02:34:19 rpi-volumio-te volumio[846]: info: Getting Push Notification urls Jul 22 02:34:22 rpi-volumio-te volumio[846]: info: Initializing connection to go-librespot Websocket Jul 22 02:34:22 rpi-volumio-te go-librespot[7559]: time="2024-07-22T02:34:22+02:00" level=debug msg="new websocket client" Jul 22 02:34:22 rpi-volumio-te volumio[846]: info: Connection to go-librespot Websocket established Jul 22 02:34:25 rpi-volumio-te volumio[846]: info: Getting Spotify volume Jul 22 02:34:25 rpi-volumio-te volumio[846]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Jul 22 02:34:25 rpi-volumio-te volumio[846]: info: CoreCommandRouter::volumioGetState Jul 22 02:34:25 rpi-volumio-te volumio[846]: info: CorePlayQueue::getTrack 0 Jul 22 02:34:25 rpi-volumio-te volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Jul 22 02:34:28 rpi-volumio-te volumio[846]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 22 02:34:28 rpi-volumio-te volumio[846]: [t [Error]: A network error (such as timeout, interrupted connection or unreachable host) has occurred.] { Jul 22 02:34:28 rpi-volumio-te volumio[846]: code: 'auth/network-request-failed', Jul 22 02:34:28 rpi-volumio-te volumio[846]: a: null Jul 22 02:34:28 rpi-volumio-te volumio[846]: } Jul 22 02:34:28 rpi-volumio-te volumio[846]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 22 02:34:29 rpi-volumio-te sudo[7575]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-22 02:33 Jul 22 02:34:29 rpi-volumio-te sudo[7575]: 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="e7445fab547cd22e23d9bef72406cfb610bc1d7d" VOLUMIO_FE_VERSION="5d5e99f8f803b3ec5fc5e8ca13bb4023600f3eee" VOLUMIO_FE3_VERSION="a6ae210575eae1ff43f06ab71e1cd17576840623" VOLUMIO_BE_VERSION="a9e1e1dd6072ffb15c0fcb8938d9ea0d8900c0da" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 24 Apr 2024 02:10:14 PM CEST" VOLUMIO_VERSION="3.661" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5bdefd4af4423fd17aacb83a8538bf1f"