-- 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"