-- Logs begin at Mon 2023-08-28 10:03:55 CEST, end at Sat 2025-06-28 08:46:45 CEST. -- Jun 28 08:45:00 volumio2 go-librespot[24997]: time="2025-06-28T08:45:00+02:00" level=debug msg="new websocket client" Jun 28 08:45:00 volumio2 volumio[873]: info: Connection to go-librespot Websocket established Jun 28 08:45:03 volumio2 volumio[873]: info: Getting Spotify volume Jun 28 08:45:03 volumio2 volumio[873]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Jun 28 08:45:03 volumio2 volumio[873]: info: CoreCommandRouter::volumioGetState Jun 28 08:45:03 volumio2 volumio[873]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Jun 28 08:45:21 volumio2 go-librespot[24997]: time="2025-06-28T08:45:21+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-gae2.spotify.com:80]" Jun 28 08:45:21 volumio2 go-librespot[24997]: time="2025-06-28T08:45:21+02: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]" Jun 28 08:45:21 volumio2 go-librespot[24997]: time="2025-06-28T08:45:21+02: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]" Jun 28 08:45:21 volumio2 go-librespot[24997]: time="2025-06-28T08:45:21+02:00" level=debug msg="zeroconf server listening on port 41333" Jun 28 08:45:21 volumio2 go-librespot[24997]: time="2025-06-28T08:45:21+02:00" level=debug msg="obtained new client token: AAD2X9tgA3ZSGzzaqJH2WHYpJklRrTOydVHCL2Al9GxUWTGIRujW3SEGTWVi3r4ZnS12/JFGWpGFL4PazLShBEQNiZdtNHB/+ZYBQJekmHs4i/rnW+DDZZ0gArtPtKs9TdMBzHpiizrkax9xAQiA4WKFhy38FyGbNOMSI4hwBHtbKufsb3ipsNfqOb+HCVnGgNV9E4fy/DGcYSxk8o5WUeOCjlWXaqb1jRuXZ0POuVyinvLq8XqQpuawALVp" Jun 28 08:45:21 volumio2 go-librespot[24997]: time="2025-06-28T08:45:21+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jun 28 08:45:21 volumio2 go-librespot[24997]: time="2025-06-28T08:45:21+02:00" level=debug msg="completed keyexchange" Jun 28 08:45:22 volumio2 go-librespot[24997]: time="2025-06-28T08:45:22+02:00" level=debug msg="completed challenge" Jun 28 08:45:22 volumio2 go-librespot[24997]: time="2025-06-28T08:45:22+02:00" level=debug msg="authenticated as 1151901839" Jun 28 08:45:43 volumio2 volumio[873]: info: Tunnel connection is inactive, restarting it Jun 28 08:45:43 volumio2 volumio[873]: info: Starting Tunnel 1 Jun 28 08:45:43 volumio2 volumio[873]: info: Starting Tunnel Connection Checker Jun 28 08:45:43 volumio2 sudo[25014]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Jun 28 08:45:43 volumio2 sudo[25014]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 28 08:45:43 volumio2 autossh[24950]: received signal to exit (15) Jun 28 08:45:43 volumio2 systemd[1]: Stopping MyVolumio SSH Tunnel... Jun 28 08:45:43 volumio2 systemd[1]: sshtunnel.service: Main process exited, code=killed, status=15/TERM Jun 28 08:45:43 volumio2 systemd[1]: sshtunnel.service: Succeeded. Jun 28 08:45:43 volumio2 systemd[1]: Stopped MyVolumio SSH Tunnel. Jun 28 08:45:43 volumio2 volumio[873]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 28 08:45:43 volumio2 systemd[1]: Started MyVolumio SSH Tunnel. Jun 28 08:45:43 volumio2 volumio[873]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jun 28 08:45:43 volumio2 sudo[25014]: pam_unix(sudo:session): session closed for user root Jun 28 08:45:43 volumio2 volumio[873]: info: Remote SSH Started Jun 28 08:45:44 volumio2 autossh[25017]: port set to 0, monitoring disabled Jun 28 08:45:44 volumio2 autossh[25017]: starting ssh (count 1) Jun 28 08:45:44 volumio2 autossh[25017]: ssh child pid is 25020 Jun 28 08:45:44 volumio2 volumio[873]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Jun 28 08:45:44 volumio2 volumio[873]: info: CoreCommandRouter::volumioGetState Jun 28 08:45:48 volumio2 go-librespot[24997]: time="2025-06-28T08:45:48+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" Jun 28 08:45:48 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 28 08:45:48 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 28 08:45:48 volumio2 volumio[873]: (node:873) UnhandledPromiseRejectionWarning: Error: socket hang up Jun 28 08:45:48 volumio2 volumio[873]: at connResetException (internal/errors.js:607:14) Jun 28 08:45:48 volumio2 volumio[873]: at Socket.socketOnEnd (_http_client.js:493:23) Jun 28 08:45:48 volumio2 volumio[873]: at Socket.emit (events.js:327:22) Jun 28 08:45:48 volumio2 volumio[873]: at endReadableNT (internal/streams/readable.js:1327:12) Jun 28 08:45:48 volumio2 volumio[873]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jun 28 08:45:48 volumio2 volumio[873]: (node:873) 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: 36) Jun 28 08:45:48 volumio2 volumio[873]: info: Connection to go-librespot Websocket closed Jun 28 08:45:50 volumio2 volumiossh-tunnel[25016]: Warning: Permanently added '[eu2.myvolumio.org]:2222,[185.14.187.123]:2222' (RSA) to the list of known hosts. Jun 28 08:45:51 volumio2 volumio[873]: info: Initializing connection to go-librespot Websocket Jun 28 08:45:51 volumio2 volumio[873]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 28 08:45:51 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 28 08:45:51 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 71. Jun 28 08:45:51 volumio2 systemd[1]: Stopped go-librespot Daemon. Jun 28 08:45:51 volumio2 systemd[1]: Started go-librespot Daemon. Jun 28 08:45:51 volumio2 go-librespot[25021]: Librespot-go daemon starting... Jun 28 08:45:51 volumio2 go-librespot[25021]: time="2025-06-28T08:45:51+02:00" level=info msg="generated new device id: 8d395c7cfb71a3940b728f51918d5fc602ad84ed" Jun 28 08:45:51 volumio2 go-librespot[25021]: time="2025-06-28T08:45:51+02:00" level=debug msg="stored credentials found for 1151901839" Jun 28 08:45:54 volumio2 volumio[873]: info: Initializing connection to go-librespot Websocket Jun 28 08:45:55 volumio2 go-librespot[25021]: time="2025-06-28T08:45:55+02:00" level=debug msg="new websocket client" Jun 28 08:45:55 volumio2 volumio[873]: info: Connection to go-librespot Websocket established Jun 28 08:45:58 volumio2 volumio[873]: info: Getting Spotify volume Jun 28 08:45:58 volumio2 volumio[873]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Jun 28 08:45:58 volumio2 volumio[873]: info: CoreCommandRouter::volumioGetState Jun 28 08:45:58 volumio2 volumio[873]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Jun 28 08:46:21 volumio2 go-librespot[25021]: time="2025-06-28T08:46:21+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: i/o timeout" Jun 28 08:46:21 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 28 08:46:21 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 28 08:46:21 volumio2 volumio[873]: (node:873) UnhandledPromiseRejectionWarning: Error: socket hang up Jun 28 08:46:21 volumio2 volumio[873]: at connResetException (internal/errors.js:607:14) Jun 28 08:46:21 volumio2 volumio[873]: at Socket.socketOnEnd (_http_client.js:493:23) Jun 28 08:46:21 volumio2 volumio[873]: at Socket.emit (events.js:327:22) Jun 28 08:46:21 volumio2 volumio[873]: at endReadableNT (internal/streams/readable.js:1327:12) Jun 28 08:46:21 volumio2 volumio[873]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jun 28 08:46:21 volumio2 volumio[873]: (node:873) 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: 37) Jun 28 08:46:21 volumio2 volumio[873]: info: Connection to go-librespot Websocket closed Jun 28 08:46:24 volumio2 volumio[873]: info: Initializing connection to go-librespot Websocket Jun 28 08:46:24 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 28 08:46:24 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 72. Jun 28 08:46:24 volumio2 systemd[1]: Stopped go-librespot Daemon. Jun 28 08:46:24 volumio2 systemd[1]: Started go-librespot Daemon. Jun 28 08:46:24 volumio2 go-librespot[25031]: Librespot-go daemon starting... Jun 28 08:46:24 volumio2 go-librespot[25031]: time="2025-06-28T08:46:24+02:00" level=info msg="generated new device id: 9be532650d936d36786b1ed3d9f2ab85bda495f6" Jun 28 08:46:24 volumio2 go-librespot[25031]: time="2025-06-28T08:46:24+02:00" level=debug msg="stored credentials found for 1151901839" Jun 28 08:46:25 volumio2 go-librespot[25031]: time="2025-06-28T08:46:25+02:00" level=debug msg="new websocket client" Jun 28 08:46:25 volumio2 volumio[873]: info: Connection to go-librespot Websocket established Jun 28 08:46:28 volumio2 volumio[873]: info: Getting Spotify volume Jun 28 08:46:28 volumio2 volumio[873]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Jun 28 08:46:28 volumio2 volumio[873]: info: CoreCommandRouter::volumioGetState Jun 28 08:46:28 volumio2 volumio[873]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Jun 28 08:46:29 volumio2 go-librespot[25031]: time="2025-06-28T08:46:29+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]" Jun 28 08:46:29 volumio2 go-librespot[25031]: time="2025-06-28T08:46:29+02: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]" Jun 28 08:46:29 volumio2 go-librespot[25031]: time="2025-06-28T08:46:29+02: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]" Jun 28 08:46:29 volumio2 go-librespot[25031]: time="2025-06-28T08:46:29+02:00" level=debug msg="zeroconf server listening on port 35933" Jun 28 08:46:44 volumio2 volumio[873]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 28 08:46:44 volumio2 volumio[873]: [t [Error]: A network error (such as timeout, interrupted connection or unreachable host) has occurred.] { Jun 28 08:46:44 volumio2 volumio[873]: code: 'auth/network-request-failed', Jun 28 08:46:44 volumio2 volumio[873]: a: null Jun 28 08:46:44 volumio2 volumio[873]: } Jun 28 08:46:44 volumio2 volumio[873]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 28 08:46:45 volumio2 sudo[25049]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-28 08:45 Jun 28 08:46:45 volumio2 sudo[25049]: 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="c87c6e2b1ae33dc5801986cbcbe970898b92e7b4" VOLUMIO_FE_VERSION="c433755e569617abac52264d17ad61be303ef463" VOLUMIO_FE3_VERSION="2419ddd8e895c5bdc456962163c9dc7c0f187aa7" VOLUMIO_BE_VERSION="b949d6001d7e656b4668f31c119d2247cdf45158" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 30 Mar 2023 05:45:03 PM CEST" VOLUMIO_VERSION="3.449" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="6428d8e2c06e98483f5c5d77e8f01989"