Apr 12 13:36:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 62.
Apr 12 13:36:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:00 volumio go-librespot[2740]: go-librespot daemon starting...
Apr 12 13:36:00 volumio go-librespot[2741]: time="2026-04-12T13:36:00+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:00 volumio go-librespot[2741]: time="2026-04-12T13:36:00+02:00" level=debug msg="app state loaded"
Apr 12 13:36:00 volumio go-librespot[2741]: time="2026-04-12T13:36:00+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:00 volumio go-librespot[2741]: time="2026-04-12T13:36:00+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"
Apr 12 13:36:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:02 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:02 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 63.
Apr 12 13:36:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:04 volumio go-librespot[2749]: go-librespot daemon starting...
Apr 12 13:36:04 volumio go-librespot[2750]: time="2026-04-12T13:36:04+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:04 volumio go-librespot[2750]: time="2026-04-12T13:36:04+02:00" level=debug msg="app state loaded"
Apr 12 13:36:04 volumio go-librespot[2750]: time="2026-04-12T13:36:04+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:04 volumio go-librespot[2750]: time="2026-04-12T13:36:04+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"
Apr 12 13:36:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:05 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:05 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 64.
Apr 12 13:36:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:07 volumio go-librespot[2758]: go-librespot daemon starting...
Apr 12 13:36:07 volumio go-librespot[2759]: time="2026-04-12T13:36:07+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:07 volumio go-librespot[2759]: time="2026-04-12T13:36:07+02:00" level=debug msg="app state loaded"
Apr 12 13:36:07 volumio go-librespot[2759]: time="2026-04-12T13:36:07+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:07 volumio go-librespot[2759]: time="2026-04-12T13:36:07+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"
Apr 12 13:36:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:08 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:08 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:08 volumio volumio5-onboarding[2639]: failed to bootstrap state: failed to check for software update: could not check for updates: context deadline exceeded
Apr 12 13:36:08 volumio systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:08 volumio systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'.
Apr 12 13:36:08 volumio systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 8.
Apr 12 13:36:08 volumio systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server.
Apr 12 13:36:08 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server.
Apr 12 13:36:08 volumio volumio5-onboarding[2781]: time=2026-04-12T13:36:08.943+02:00 level=INFO msg="running volumio5-device-gateway" version=10ca7e93+CHANGES buildDate=2026-03-06T14:30:20Z
Apr 12 13:36:09 volumio volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4
Apr 12 13:36:09 volumio volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4
Apr 12 13:36:09 volumio volumio[1214]: info: Received Get System Info
Apr 12 13:36:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Apr 12 13:36:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Apr 12 13:36:09 volumio volumio[1214]: info: Discovery: Getting this device information
Apr 12 13:36:09 volumio volumio[1214]: info: CoreCommandRouter::volumioGetState
Apr 12 13:36:09 volumio volumio[1214]: info: CorePlayQueue::getTrack 0
Apr 12 13:36:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Apr 12 13:36:09 volumio volumio5-onboarding[2781]: time=2026-04-12T13:36:09.066+02:00 level=INFO msg="system info for 5bc45c9736dcfbee457186f989f20019" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.103
Apr 12 13:36:09 volumio volumio5-onboarding[2781]: time=2026-04-12T13:36:09.085+02:00 level=INFO msg="bootstrapping state" hasInternet=true
Apr 12 13:36:09 volumio volumio[1214]: info: Received Get System Info
Apr 12 13:36:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Apr 12 13:36:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Apr 12 13:36:09 volumio volumio[1214]: info: Discovery: Getting this device information
Apr 12 13:36:09 volumio volumio[1214]: info: CoreCommandRouter::volumioGetState
Apr 12 13:36:09 volumio volumio[1214]: info: CorePlayQueue::getTrack 0
Apr 12 13:36:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Apr 12 13:36:09 volumio volumio-remote-updater[2650]: Test mode disabled
Apr 12 13:36:09 volumio volumio-remote-updater[2650]: Alpha mode disabled
Apr 12 13:36:09 volumio volumio-remote-updater[2650]: Alpha legacy test mode disabled
Apr 12 13:36:09 volumio volumio-remote-updater[2650]: curl_easy_perform() failed: Couldn't resolve host name
Apr 12 13:36:09 volumio volumio-remote-updater[2650]: terminate called after throwing an instance of 'std::invalid_argument'
Apr 12 13:36:09 volumio volumio-remote-updater[2650]: what(): parse error - unexpected end of input
Apr 12 13:36:09 volumio systemd[1]: volumio-remote-updater.service: Main process exited, code=killed, status=6/ABRT
Apr 12 13:36:09 volumio systemd[1]: volumio-remote-updater.service: Failed with result 'signal'.
Apr 12 13:36:09 volumio systemd[1]: volumio-remote-updater.service: Scheduled restart job, restart counter is at 7.
Apr 12 13:36:09 volumio systemd[1]: Stopped volumio-remote-updater.service - Volumio Remote OTA Updater.
Apr 12 13:36:09 volumio systemd[1]: Started volumio-remote-updater.service - Volumio Remote OTA Updater.
Apr 12 13:36:09 volumio volumio-remote-updater[2791]: Volumio OTA Client: 1.7.0
Apr 12 13:36:09 volumio volumio-remote-updater[2791]: Error: No active session
Apr 12 13:36:09 volumio volumio-remote-updater[2791]: [2026-04-12 13:36:09] [connect] Successful connection
Apr 12 13:36:09 volumio volumio-remote-updater[2791]: [2026-04-12 13:36:09] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1775993769 101
Apr 12 13:36:09 volumio volumio[1214]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 4
Apr 12 13:36:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 65.
Apr 12 13:36:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:10 volumio go-librespot[2794]: go-librespot daemon starting...
Apr 12 13:36:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:10 volumio go-librespot[2795]: time="2026-04-12T13:36:10+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:10 volumio go-librespot[2795]: time="2026-04-12T13:36:10+02:00" level=debug msg="app state loaded"
Apr 12 13:36:10 volumio go-librespot[2795]: time="2026-04-12T13:36:10+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:10 volumio go-librespot[2795]: time="2026-04-12T13:36:10+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"
Apr 12 13:36:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:11 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:11 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 66.
Apr 12 13:36:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:13 volumio go-librespot[2803]: go-librespot daemon starting...
Apr 12 13:36:13 volumio go-librespot[2804]: time="2026-04-12T13:36:13+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:13 volumio go-librespot[2804]: time="2026-04-12T13:36:13+02:00" level=debug msg="app state loaded"
Apr 12 13:36:13 volumio go-librespot[2804]: time="2026-04-12T13:36:13+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:13 volumio go-librespot[2804]: time="2026-04-12T13:36:13+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"
Apr 12 13:36:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:14 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:14 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 67.
Apr 12 13:36:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:17 volumio go-librespot[2812]: go-librespot daemon starting...
Apr 12 13:36:17 volumio go-librespot[2813]: time="2026-04-12T13:36:17+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:17 volumio go-librespot[2813]: time="2026-04-12T13:36:17+02:00" level=debug msg="app state loaded"
Apr 12 13:36:17 volumio go-librespot[2813]: time="2026-04-12T13:36:17+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:17 volumio go-librespot[2813]: time="2026-04-12T13:36:17+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"
Apr 12 13:36:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:17 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:17 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 68.
Apr 12 13:36:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:20 volumio go-librespot[2835]: go-librespot daemon starting...
Apr 12 13:36:20 volumio go-librespot[2836]: time="2026-04-12T13:36:20+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:20 volumio go-librespot[2836]: time="2026-04-12T13:36:20+02:00" level=debug msg="app state loaded"
Apr 12 13:36:20 volumio go-librespot[2836]: time="2026-04-12T13:36:20+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:20 volumio go-librespot[2836]: time="2026-04-12T13:36:20+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"
Apr 12 13:36:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:20 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:20 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 69.
Apr 12 13:36:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:23 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:23 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:23 volumio go-librespot[2844]: go-librespot daemon starting...
Apr 12 13:36:23 volumio go-librespot[2845]: time="2026-04-12T13:36:23+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:23 volumio go-librespot[2845]: time="2026-04-12T13:36:23+02:00" level=debug msg="app state loaded"
Apr 12 13:36:23 volumio go-librespot[2845]: time="2026-04-12T13:36:23+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:23 volumio go-librespot[2845]: time="2026-04-12T13:36:23+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"
Apr 12 13:36:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:26 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:26 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 70.
Apr 12 13:36:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:26 volumio go-librespot[2854]: go-librespot daemon starting...
Apr 12 13:36:26 volumio go-librespot[2855]: time="2026-04-12T13:36:26+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:26 volumio go-librespot[2855]: time="2026-04-12T13:36:26+02:00" level=debug msg="app state loaded"
Apr 12 13:36:26 volumio go-librespot[2855]: time="2026-04-12T13:36:26+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:26 volumio go-librespot[2855]: time="2026-04-12T13:36:26+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"
Apr 12 13:36:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:29 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:29 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 71.
Apr 12 13:36:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:30 volumio go-librespot[2877]: go-librespot daemon starting...
Apr 12 13:36:30 volumio go-librespot[2878]: time="2026-04-12T13:36:30+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:30 volumio go-librespot[2878]: time="2026-04-12T13:36:30+02:00" level=debug msg="app state loaded"
Apr 12 13:36:30 volumio go-librespot[2878]: time="2026-04-12T13:36:30+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:30 volumio go-librespot[2878]: time="2026-04-12T13:36:30+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"
Apr 12 13:36:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:32 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:32 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 72.
Apr 12 13:36:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:33 volumio go-librespot[2886]: go-librespot daemon starting...
Apr 12 13:36:33 volumio go-librespot[2887]: time="2026-04-12T13:36:33+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:33 volumio go-librespot[2887]: time="2026-04-12T13:36:33+02:00" level=debug msg="app state loaded"
Apr 12 13:36:33 volumio go-librespot[2887]: time="2026-04-12T13:36:33+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:33 volumio go-librespot[2887]: time="2026-04-12T13:36:33+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"
Apr 12 13:36:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:35 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:35 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 73.
Apr 12 13:36:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:36 volumio go-librespot[2895]: go-librespot daemon starting...
Apr 12 13:36:36 volumio go-librespot[2896]: time="2026-04-12T13:36:36+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:36 volumio go-librespot[2896]: time="2026-04-12T13:36:36+02:00" level=debug msg="app state loaded"
Apr 12 13:36:36 volumio go-librespot[2896]: time="2026-04-12T13:36:36+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:36 volumio go-librespot[2896]: time="2026-04-12T13:36: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"
Apr 12 13:36:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:38 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:38 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:39 volumio volumio5-onboarding[2781]: failed to bootstrap state: failed to check for software update: could not check for updates: context deadline exceeded
Apr 12 13:36:39 volumio systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:39 volumio systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'.
Apr 12 13:36:39 volumio systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 9.
Apr 12 13:36:39 volumio systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server.
Apr 12 13:36:39 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server.
Apr 12 13:36:39 volumio volumio5-onboarding[2918]: time=2026-04-12T13:36:39.349+02:00 level=INFO msg="running volumio5-device-gateway" version=10ca7e93+CHANGES buildDate=2026-03-06T14:30:20Z
Apr 12 13:36:39 volumio volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4
Apr 12 13:36:39 volumio volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4
Apr 12 13:36:39 volumio volumio[1214]: info: Received Get System Info
Apr 12 13:36:39 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Apr 12 13:36:39 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Apr 12 13:36:39 volumio volumio[1214]: info: Discovery: Getting this device information
Apr 12 13:36:39 volumio volumio[1214]: info: CoreCommandRouter::volumioGetState
Apr 12 13:36:39 volumio volumio[1214]: info: CorePlayQueue::getTrack 0
Apr 12 13:36:39 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Apr 12 13:36:39 volumio volumio5-onboarding[2918]: time=2026-04-12T13:36:39.389+02:00 level=INFO msg="system info for 5bc45c9736dcfbee457186f989f20019" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.103
Apr 12 13:36:39 volumio volumio5-onboarding[2918]: time=2026-04-12T13:36:39.407+02:00 level=INFO msg="bootstrapping state" hasInternet=true
Apr 12 13:36:39 volumio volumio[1214]: info: Received Get System Info
Apr 12 13:36:39 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Apr 12 13:36:39 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Apr 12 13:36:39 volumio volumio[1214]: info: Discovery: Getting this device information
Apr 12 13:36:39 volumio volumio[1214]: info: CoreCommandRouter::volumioGetState
Apr 12 13:36:39 volumio volumio[1214]: info: CorePlayQueue::getTrack 0
Apr 12 13:36:39 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Apr 12 13:36:39 volumio volumio-remote-updater[2791]: Test mode disabled
Apr 12 13:36:39 volumio volumio-remote-updater[2791]: Alpha mode disabled
Apr 12 13:36:39 volumio volumio-remote-updater[2791]: Alpha legacy test mode disabled
Apr 12 13:36:39 volumio volumio-remote-updater[2791]: curl_easy_perform() failed: Couldn't resolve host name
Apr 12 13:36:39 volumio volumio-remote-updater[2791]: terminate called after throwing an instance of 'std::invalid_argument'
Apr 12 13:36:39 volumio volumio-remote-updater[2791]: what(): parse error - unexpected end of input
Apr 12 13:36:39 volumio systemd[1]: volumio-remote-updater.service: Main process exited, code=killed, status=6/ABRT
Apr 12 13:36:39 volumio systemd[1]: volumio-remote-updater.service: Failed with result 'signal'.
Apr 12 13:36:39 volumio systemd[1]: volumio-remote-updater.service: Scheduled restart job, restart counter is at 8.
Apr 12 13:36:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 74.
Apr 12 13:36:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:39 volumio systemd[1]: Stopped volumio-remote-updater.service - Volumio Remote OTA Updater.
Apr 12 13:36:39 volumio go-librespot[2929]: go-librespot daemon starting...
Apr 12 13:36:39 volumio systemd[1]: Started volumio-remote-updater.service - Volumio Remote OTA Updater.
Apr 12 13:36:39 volumio go-librespot[2930]: time="2026-04-12T13:36:39+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:39 volumio go-librespot[2930]: time="2026-04-12T13:36:39+02:00" level=debug msg="app state loaded"
Apr 12 13:36:39 volumio volumio-remote-updater[2931]: Volumio OTA Client: 1.7.0
Apr 12 13:36:39 volumio volumio-remote-updater[2931]: Error: No active session
Apr 12 13:36:39 volumio volumio-remote-updater[2931]: [2026-04-12 13:36:39] [connect] Successful connection
Apr 12 13:36:39 volumio go-librespot[2930]: time="2026-04-12T13:36:39+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:39 volumio volumio-remote-updater[2931]: [2026-04-12 13:36:39] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1775993799 101
Apr 12 13:36:39 volumio go-librespot[2930]: time="2026-04-12T13:36:39+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"
Apr 12 13:36:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:39 volumio volumio[1214]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 4
Apr 12 13:36:41 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:41 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 75.
Apr 12 13:36:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:43 volumio go-librespot[2940]: go-librespot daemon starting...
Apr 12 13:36:43 volumio go-librespot[2941]: time="2026-04-12T13:36:43+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:43 volumio go-librespot[2941]: time="2026-04-12T13:36:43+02:00" level=debug msg="app state loaded"
Apr 12 13:36:43 volumio go-librespot[2941]: time="2026-04-12T13:36:43+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:43 volumio go-librespot[2941]: time="2026-04-12T13:36:43+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"
Apr 12 13:36:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:44 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:44 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 76.
Apr 12 13:36:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:46 volumio go-librespot[2950]: go-librespot daemon starting...
Apr 12 13:36:46 volumio go-librespot[2951]: time="2026-04-12T13:36:46+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:46 volumio go-librespot[2951]: time="2026-04-12T13:36:46+02:00" level=debug msg="app state loaded"
Apr 12 13:36:46 volumio go-librespot[2951]: time="2026-04-12T13:36:46+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:46 volumio go-librespot[2951]: time="2026-04-12T13:36:46+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"
Apr 12 13:36:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:47 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:47 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 77.
Apr 12 13:36:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:49 volumio go-librespot[2973]: go-librespot daemon starting...
Apr 12 13:36:49 volumio go-librespot[2974]: time="2026-04-12T13:36:49+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:49 volumio go-librespot[2974]: time="2026-04-12T13:36:49+02:00" level=debug msg="app state loaded"
Apr 12 13:36:49 volumio go-librespot[2974]: time="2026-04-12T13:36:49+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:49 volumio go-librespot[2974]: time="2026-04-12T13:36:49+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"
Apr 12 13:36:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:50 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:50 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 78.
Apr 12 13:36:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:52 volumio go-librespot[2982]: go-librespot daemon starting...
Apr 12 13:36:52 volumio go-librespot[2983]: time="2026-04-12T13:36:52+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:52 volumio go-librespot[2983]: time="2026-04-12T13:36:52+02:00" level=debug msg="app state loaded"
Apr 12 13:36:52 volumio go-librespot[2983]: time="2026-04-12T13:36:52+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:52 volumio go-librespot[2983]: time="2026-04-12T13:36:52+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"
Apr 12 13:36:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:53 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:53 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 79.
Apr 12 13:36:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:56 volumio go-librespot[2991]: go-librespot daemon starting...
Apr 12 13:36:56 volumio go-librespot[2992]: time="2026-04-12T13:36:56+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:56 volumio go-librespot[2992]: time="2026-04-12T13:36:56+02:00" level=debug msg="app state loaded"
Apr 12 13:36:56 volumio go-librespot[2992]: time="2026-04-12T13:36:56+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:56 volumio go-librespot[2992]: time="2026-04-12T13:36:56+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"
Apr 12 13:36:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:56 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:56 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:36:57 volumio kernel: smsc95xx 1-1.1:1.0 eth0: Link is Down
Apr 12 13:36:57 volumio dhcpcd[655]: eth0: carrier lost
Apr 12 13:36:57 volumio dhcpcd[723]: eth0: carrier lost
Apr 12 13:36:57 volumio avahi-daemon[662]: Withdrawing address record for 192.168.2.101 on eth0.
Apr 12 13:36:57 volumio avahi-daemon[662]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.2.101.
Apr 12 13:36:57 volumio avahi-daemon[662]: Interface eth0.IPv4 no longer relevant for mDNS.
Apr 12 13:36:57 volumio dhcpcd[655]: eth0: deleting route to 192.168.2.0/24
Apr 12 13:36:57 volumio dhcpcd[655]: eth0: deleting default route via 192.168.2.1
Apr 12 13:36:57 volumio dhcpcd[723]: eth0: deleting route to 192.168.2.0/24
Apr 12 13:36:57 volumio dhcpcd[723]: eth0: deleting default route via 192.168.2.1
Apr 12 13:36:57 volumio volumio[1214]: info: Discovery: A device disappeared from network
Apr 12 13:36:57 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0.
Apr 12 13:36:57 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0...
Apr 12 13:36:57 volumio systemd[1]: welcome.service: Deactivated successfully.
Apr 12 13:36:57 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console.
Apr 12 13:36:57 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console...
Apr 12 13:36:58 volumio systemd[1]: Starting welcome.service - Show a welcome message on console...
Apr 12 13:36:58 volumio welcome[3055]: Resolved ip:[0]
Apr 12 13:36:58 volumio systemd[1]: Finished welcome.service - Show a welcome message on console.
Apr 12 13:36:58 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0.
Apr 12 13:36:58 volumio ifplugd(eth0)[984]: Link beat lost.
Apr 12 13:36:58 volumio volumio[1214]: info: Volumio Network Manager: Network status updated: 0
Apr 12 13:36:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 80.
Apr 12 13:36:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:36:59 volumio go-librespot[3074]: go-librespot daemon starting...
Apr 12 13:36:59 volumio go-librespot[3075]: time="2026-04-12T13:36:59+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:36:59 volumio go-librespot[3075]: time="2026-04-12T13:36:59+02:00" level=debug msg="app state loaded"
Apr 12 13:36:59 volumio go-librespot[3075]: time="2026-04-12T13:36:59+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:36:59 volumio go-librespot[3075]: time="2026-04-12T13:36: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"
Apr 12 13:36:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:36:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:36:59 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:36:59 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: AggregateError
Apr 12 13:36:59 volumio ntpd[971]: IO: Deleting interface #3 eth0, 192.168.2.101#123, interface stats: received=47, sent=47, dropped=0, active_time=309 secs
Apr 12 13:36:59 volumio ntpd[971]: PROTO: 193.70.94.182 unlink local addr 192.168.2.101 ->
Apr 12 13:36:59 volumio ntpd[971]: PROTO: 195.46.37.22 unlink local addr 192.168.2.101 ->
Apr 12 13:36:59 volumio ntpd[971]: PROTO: 91.212.242.21 unlink local addr 192.168.2.101 ->
Apr 12 13:36:59 volumio ntpd[971]: PROTO: 162.159.200.1 unlink local addr 192.168.2.101 ->
Apr 12 13:37:00 volumio dhcpcd[723]: eth0: carrier acquired
Apr 12 13:37:00 volumio dhcpcd[655]: eth0: carrier acquired
Apr 12 13:37:00 volumio kernel: smsc95xx 1-1.1:1.0 eth0: Link is Up - 100Mbps/Full - flow control off
Apr 12 13:37:00 volumio dhcpcd[723]: eth0: IAID eb:4b:e1:20
Apr 12 13:37:00 volumio dhcpcd[655]: eth0: IAID eb:4b:e1:20
Apr 12 13:37:00 volumio dhcpcd[723]: eth0: soliciting an IPv6 router
Apr 12 13:37:00 volumio ifplugd(eth0)[984]: Link beat detected.
Apr 12 13:37:00 volumio dhcpcd[655]: eth0: soliciting an IPv6 router
Apr 12 13:37:00 volumio dhcpcd[655]: eth0: rebinding lease of 192.168.2.101
Apr 12 13:37:00 volumio dhcpcd[655]: eth0: probing address 192.168.2.101/24
Apr 12 13:37:01 volumio dhcpcd[723]: eth0: rebinding lease of 192.168.2.101
Apr 12 13:37:01 volumio dhcpcd[723]: eth0: probing address 192.168.2.101/24
Apr 12 13:37:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 81.
Apr 12 13:37:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:37:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:37:02 volumio go-librespot[3089]: go-librespot daemon starting...
Apr 12 13:37:02 volumio go-librespot[3090]: time="2026-04-12T13:37:02+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:37:02 volumio go-librespot[3090]: time="2026-04-12T13:37:02+02:00" level=debug msg="app state loaded"
Apr 12 13:37:02 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:37:02 volumio go-librespot[3090]: time="2026-04-12T13:37:02+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:37:02 volumio go-librespot[3090]: time="2026-04-12T13:37:02+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"
Apr 12 13:37:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:37:02 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: socket hang up
Apr 12 13:37:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:37:05 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:37:05 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: AggregateError
Apr 12 13:37:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 82.
Apr 12 13:37:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:37:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:37:05 volumio go-librespot[3099]: go-librespot daemon starting...
Apr 12 13:37:05 volumio go-librespot[3100]: time="2026-04-12T13:37:05+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:37:05 volumio go-librespot[3100]: time="2026-04-12T13:37:05+02:00" level=debug msg="app state loaded"
Apr 12 13:37:05 volumio go-librespot[3100]: time="2026-04-12T13:37:05+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:37:05 volumio go-librespot[3100]: time="2026-04-12T13:37:05+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"
Apr 12 13:37:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:37:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 12 13:37:06 volumio dhcpcd[655]: eth0: leased 192.168.2.101 for 43200 seconds
Apr 12 13:37:06 volumio avahi-daemon[662]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.2.101.
Apr 12 13:37:06 volumio avahi-daemon[662]: New relevant interface eth0.IPv4 for mDNS.
Apr 12 13:37:06 volumio avahi-daemon[662]: Registering new address record for 192.168.2.101 on eth0.IPv4.
Apr 12 13:37:06 volumio dhcpcd[655]: eth0: adding route to 192.168.2.0/24
Apr 12 13:37:06 volumio dhcpcd[655]: eth0: adding default route via 192.168.2.1
Apr 12 13:37:06 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0.
Apr 12 13:37:06 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0...
Apr 12 13:37:06 volumio systemd[1]: welcome.service: Deactivated successfully.
Apr 12 13:37:06 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console.
Apr 12 13:37:06 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console...
Apr 12 13:37:06 volumio systemd[1]: Starting welcome.service - Show a welcome message on console...
Apr 12 13:37:06 volumio welcome[3131]: Resolved ip:[1] 192.168.2.101
Apr 12 13:37:06 volumio systemd[1]: Finished welcome.service - Show a welcome message on console.
Apr 12 13:37:06 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0.
Apr 12 13:37:06 volumio dhcpcd[723]: eth0: leased 192.168.2.101 for 43200 seconds
Apr 12 13:37:06 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0.
Apr 12 13:37:06 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0...
Apr 12 13:37:06 volumio systemd[1]: welcome.service: Deactivated successfully.
Apr 12 13:37:06 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console.
Apr 12 13:37:06 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console...
Apr 12 13:37:06 volumio dhcpcd[723]: eth0: adding route to 192.168.2.0/24
Apr 12 13:37:06 volumio dhcpcd[723]: eth0: adding default route via 192.168.2.1
Apr 12 13:37:06 volumio systemd[1]: Starting welcome.service - Show a welcome message on console...
Apr 12 13:37:06 volumio welcome[3157]: Resolved ip:[1] 192.168.2.101
Apr 12 13:37:07 volumio systemd[1]: Finished welcome.service - Show a welcome message on console.
Apr 12 13:37:07 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0.
Apr 12 13:37:07 volumio volumio[1214]: info: Discovery: adding bfa3d19f-3b65-4b6b-9c76-4d08f58ab72b
Apr 12 13:37:07 volumio volumio[1214]: info: Discovery: Found device Volumio
Apr 12 13:37:07 volumio volumio[1214]: info: CoreCommandRouter::volumioGetState
Apr 12 13:37:07 volumio volumio[1214]: info: CorePlayQueue::getTrack 0
Apr 12 13:37:08 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:37:08 volumio volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 12 13:37:08 volumio volumio[1214]: info: Volumio Network Manager: Network status updated: 1
Apr 12 13:37:08 volumio ntpd[971]: IO: Listen normally on 4 eth0 192.168.2.101:123
Apr 12 13:37:08 volumio ntpd[971]: IO: new interface(s) found: waking up resolver
Apr 12 13:37:08 volumio ntpd[971]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101
Apr 12 13:37:08 volumio ntpd[971]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101
Apr 12 13:37:08 volumio ntpd[971]: DNS: Pool skipping: 195.46.37.22
Apr 12 13:37:08 volumio ntpd[971]: DNS: Pool skipping: 162.159.200.1
Apr 12 13:37:08 volumio ntpd[971]: DNS: Pool taking: 89.250.197.242
Apr 12 13:37:08 volumio ntpd[971]: DNS: Pool taking: 46.175.224.7
Apr 12 13:37:08 volumio ntpd[971]: DNS: dns_take_status: 3.debian.pool.ntp.org=>good, 8
Apr 12 13:37:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 83.
Apr 12 13:37:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:37:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Apr 12 13:37:09 volumio go-librespot[3177]: go-librespot daemon starting...
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=info msg="running go-librespot 0.7.1"
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=debug msg="app state loaded"
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 12 13:37:09 volumio volumio5-onboarding[2918]: failed to bootstrap state: failed to check for software update: could not check for updates: context deadline exceeded
Apr 12 13:37:09 volumio systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE
Apr 12 13:37:09 volumio systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'.
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]"
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]"
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]"
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=info msg="zeroconf server listening on port 39207"
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration"
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=debug msg="obtained new client token: AADZVBh3Dc4fIx8IWkICQWLwLo7Xh1QYCIwblpV/b7E3K2drG070ltGAPtV1XTA6TNnRjM3whJYbJEsZbhTUG2NlH1L2dOaADzdEt3K9iRmTYcBItJCw2sp1LYF7uGPke86dbTXcTvBGo4n0Tyy+i/kZ9WLKVtozFhH1g6jFZeXwQqUED2EzCXC94Qi9SNBaNo8xmyaQlr4634OBPsO2zUTOqrKk5UGlYzPX4LH1C0Vz6DnD5IsDV0Hy"
Apr 12 13:37:09 volumio systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 10.
Apr 12 13:37:09 volumio ntpd[971]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101
Apr 12 13:37:09 volumio systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server.
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070"
Apr 12 13:37:09 volumio ntpd[971]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101
Apr 12 13:37:09 volumio ntpd[971]: DNS: Pool skipping: 193.70.94.182
Apr 12 13:37:09 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server.
Apr 12 13:37:09 volumio ntpd[971]: DNS: Pool taking: 212.132.97.26
Apr 12 13:37:09 volumio ntpd[971]: DNS: Pool skipping: 162.159.200.1
Apr 12 13:37:09 volumio ntpd[971]: DNS: Pool skipping: 46.175.224.7
Apr 12 13:37:09 volumio ntpd[971]: DNS: Pool taking: 2a01:239:2a6:d500::1
Apr 12 13:37:09 volumio ntpd[971]: DNS: Pool taking: 2606:4700:f1::1
Apr 12 13:37:09 volumio ntpd[971]: DNS: Pool taking: 2a0d:5440::24
Apr 12 13:37:09 volumio ntpd[971]: DNS: Pool taking: 2a05:f480:2400:18af:5400:4ff:fe0c:1486
Apr 12 13:37:09 volumio ntpd[971]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8
Apr 12 13:37:09 volumio volumio5-onboarding[3188]: time=2026-04-12T13:37:09.820+02:00 level=INFO msg="running volumio5-device-gateway" version=10ca7e93+CHANGES buildDate=2026-03-06T14:30:20Z
Apr 12 13:37:09 volumio volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4
Apr 12 13:37:09 volumio volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=debug msg="completed keyexchange"
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=debug msg="completed challenge"
Apr 12 13:37:09 volumio volumio[1214]: info: Received Get System Info
Apr 12 13:37:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Apr 12 13:37:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Apr 12 13:37:09 volumio volumio[1214]: info: Discovery: Getting this device information
Apr 12 13:37:09 volumio volumio[1214]: info: CoreCommandRouter::volumioGetState
Apr 12 13:37:09 volumio volumio[1214]: info: CorePlayQueue::getTrack 0
Apr 12 13:37:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Apr 12 13:37:09 volumio volumio5-onboarding[3188]: time=2026-04-12T13:37:09.870+02:00 level=INFO msg="system info for 5bc45c9736dcfbee457186f989f20019" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.103
Apr 12 13:37:09 volumio volumio5-onboarding[3188]: time=2026-04-12T13:37:09.890+02:00 level=INFO msg="bootstrapping state" hasInternet=true
Apr 12 13:37:09 volumio volumio[1214]: info: Received Get System Info
Apr 12 13:37:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Apr 12 13:37:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Apr 12 13:37:09 volumio volumio[1214]: info: Discovery: Getting this device information
Apr 12 13:37:09 volumio volumio[1214]: info: CoreCommandRouter::volumioGetState
Apr 12 13:37:09 volumio volumio[1214]: info: CorePlayQueue::getTrack 0
Apr 12 13:37:09 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Apr 12 13:37:09 volumio volumio-remote-updater[2931]: Test mode disabled
Apr 12 13:37:09 volumio volumio-remote-updater[2931]: Alpha mode disabled
Apr 12 13:37:09 volumio volumio-remote-updater[2931]: Alpha legacy test mode disabled
Apr 12 13:37:09 volumio go-librespot[3178]: time="2026-04-12T13:37:09+02:00" level=info msg="authenticated AP" username="wa*****26"
Apr 12 13:37:10 volumio volumio[1214]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"FIXES
- Fix for missing PWM backlight module
- Fix for crash loop on Onboarding plugin
NEW ADDITIONS
- Bump RPi/CM4 kernel to 6.12.74
","title":"Update v4.119","updateavailable":true}
Apr 12 13:37:10 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Apr 12 13:37:10 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Apr 12 13:37:10 volumio volumio5-onboarding[3188]: time=2026-04-12T13:37:10.116+02:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory"
Apr 12 13:37:10 volumio volumio5-onboarding[3188]: time=2026-04-12T13:37:10.117+02:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory"
Apr 12 13:37:10 volumio volumio5-onboarding[3188]: time=2026-04-12T13:37:10.117+02:00 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory"
Apr 12 13:37:10 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Apr 12 13:37:10 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Apr 12 13:37:10 volumio volumio[1214]: info: Received Get System Info
Apr 12 13:37:10 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Apr 12 13:37:10 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Apr 12 13:37:10 volumio volumio[1214]: info: Discovery: Getting this device information
Apr 12 13:37:10 volumio volumio[1214]: info: CoreCommandRouter::volumioGetState
Apr 12 13:37:10 volumio volumio[1214]: info: CorePlayQueue::getTrack 0
Apr 12 13:37:10 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Apr 12 13:37:10 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
Apr 12 13:37:10 volumio volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
Apr 12 13:37:10 volumio volumio5-onboarding[3188]: time=2026-04-12T13:37:10.142+02:00 level=INFO msg="enabling local network discovery"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=info msg="authenticated Login5" username="wa*****26"
Apr 12 13:37:10 volumio volumio5-onboarding[3188]: time=2026-04-12T13:37:10.165+02:00 level=INFO msg="enabling BLE discovery"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=debug msg="initializing zeroconf session" username="wa*****26"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=debug msg="dealer connection opened"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=trace msg="starting accesspoint recv loop"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=trace msg="starting dealer recv loop"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=trace msg="received accesspoint ping"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=debug msg="received connection id: MGNjNmZlZjAtMTQx...RjhGNjA4NzUwOA=="
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=trace msg="received accesspoint pong ack"
Apr 12 13:37:10 volumio go-librespot[3178]: time="2026-04-12T13:37:10+02:00" level=debug msg="put connect state because NEW_DEVICE"
Apr 12 13:37:11 volumio volumio5-onboarding[3188]: time=2026-04-12T13:37:11.188+02:00 level=INFO msg="service successfully established" component=discovery/localnet
Apr 12 13:37:11 volumio volumio[1214]: info: Initializing connection to go-librespot Websocket
Apr 12 13:37:11 volumio go-librespot[3178]: time="2026-04-12T13:37:11+02:00" level=debug msg="new websocket client"
Apr 12 13:37:11 volumio volumio[1214]: info: Connection to go-librespot Websocket established
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=debug msg="handling transfer player command from f7db85937ee572a4fa2a4dbd3bb0afdc50eab3a4"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=debug msg="resolved context of track" uri="spotify:album:3jlE37AdgcZbfsfyMutyCE"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:album:3jlE37AdgcZbfsfyMutyCE"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=debug msg="loading track (paused: false, position: 2044ms)" uri="spotify:track:0REo0vbZOgwJ7efhYEXy6J"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=trace msg="emitting websocket event: will_play"
Apr 12 13:37:12 volumio volumio[1214]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:3jlE37AdgcZbfsfyMutyCE","uri":"spotify:track:0REo0vbZOgwJ7efhYEXy6J","play_origin":"album"}}
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1130"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=debug msg="selected format OGG_VORBIS_320 (d1b2bb2161f07bc66d24e8a27179cd434ccd722c)" uri="spotify:track:0REo0vbZOgwJ7efhYEXy6J"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=debug msg="requested aes key for file d1b2bb2161f07bc66d24e8a27179cd434ccd722c, gid: 0REo0vbZOgwJ7efhYEXy6J"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0REo0vbZOgwJ7efhYEXy6J"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=debug msg="fetched first chunk of 18, total size is 9094800 bytes" uri="spotify:track:0REo0vbZOgwJ7efhYEXy6J"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=trace msg="seek to 2044ms (diff: 61ms, samples: 90140, bytes: 84620)" uri="spotify:track:0REo0vbZOgwJ7efhYEXy6J"
Apr 12 13:37:12 volumio go-librespot[3178]: time="2026-04-12T13:37:12+02:00" level=debug msg="created new output device"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=info msg="loaded track \"Fakest Bitch\" (paused: false, position: 2044ms, duration: 259234ms, prefetched: false)" uri="spotify:track:0REo0vbZOgwJ7efhYEXy6J"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=trace msg="scheduling prefetch in 226s"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=trace msg="emitting websocket event: metadata"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=trace msg="emitting websocket event: active"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=debug msg="sending successful reply for dealer request"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
Apr 12 13:37:13 volumio volumio[1214]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0REo0vbZOgwJ7efhYEXy6J","name":"Fakest Bitch","artist_names":["London Grammar"],"album_name":"The Greatest Love","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a6938e2434bf671772a0813f","position":2044,"duration":259234,"release_date":"year:2024 month:9 day:13","track_number":2,"disc_number":1}}
Apr 12 13:37:13 volumio volumio[1214]: SPOTIFY: received: {"type":"active","data":null}
Apr 12 13:37:13 volumio volumio[1214]: info: Aligning Spotify Volume to Volumio Volume
Apr 12 13:37:13 volumio volumio[1214]: info: CoreCommandRouter::volumioGetState
Apr 12 13:37:13 volumio volumio[1214]: info: CorePlayQueue::getTrack 0
Apr 12 13:37:13 volumio volumio[1214]: info: Setting Spotify Volume from Volumio: 100
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:0REo0vbZOgwJ7efhYEXy6J"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=trace msg="emitting websocket event: playing"
Apr 12 13:37:13 volumio volumio[1214]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:album:3jlE37AdgcZbfsfyMutyCE","uri":"spotify:track:0REo0vbZOgwJ7efhYEXy6J","resume":false,"play_origin":"album"}}
Apr 12 13:37:13 volumio volumio[1214]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Apr 12 13:37:13 volumio volumio[1214]: TypeError: Cannot read properties of undefined (reading 'service')
Apr 12 13:37:13 volumio volumio[1214]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50)
Apr 12 13:37:13 volumio volumio[1214]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18)
Apr 12 13:37:13 volumio volumio[1214]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14)
Apr 12 13:37:13 volumio volumio[1214]: at WebSocket.emit (node:events:514:28)
Apr 12 13:37:13 volumio volumio[1214]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20)
Apr 12 13:37:13 volumio volumio[1214]: at Receiver.emit (node:events:514:28)
Apr 12 13:37:13 volumio volumio[1214]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14)
Apr 12 13:37:13 volumio volumio[1214]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10)
Apr 12 13:37:13 volumio volumio[1214]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16)
Apr 12 13:37:13 volumio volumio[1214]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10)
Apr 12 13:37:13 volumio volumio[1214]: at writeOrBuffer (node:internal/streams/writable:399:12)
Apr 12 13:37:13 volumio volumio[1214]: at _write (node:internal/streams/writable:340:10)
Apr 12 13:37:13 volumio volumio[1214]: at Writable.write (node:internal/streams/writable:344:10)
Apr 12 13:37:13 volumio volumio[1214]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35)
Apr 12 13:37:13 volumio volumio[1214]: at Socket.emit (node:events:514:28)
Apr 12 13:37:13 volumio volumio[1214]: at addChunk (node:internal/streams/readable:343:12)
Apr 12 13:37:13 volumio volumio[1214]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:0REo0vbZOgwJ7efhYEXy6J"
Apr 12 13:37:13 volumio go-librespot[3178]: time="2026-04-12T13:37:13+02:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:0REo0vbZOgwJ7efhYEXy6J"
Apr 12 13:37:14 volumio sudo[3224]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-04-12 13:36'
Apr 12 13:37:14 volumio sudo[3224]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)"
NAME="Raspbian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
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="dc61260dec5515dafd2b634881860b4c46c919ff"
VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd"
VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2"
VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026"
VOLUMIO_VERSION="4.103"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"