Sep 25 04:16:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031888. Sep 25 04:16:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:00 volumio go-librespot[31337]: go-librespot daemon starting... Sep 25 04:16:00 volumio go-librespot[31338]: time="2026-09-25T04:16:00+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:00 volumio go-librespot[31338]: time="2026-09-25T04:16:00+01:00" level=debug msg="app state loaded" Sep 25 04:16:00 volumio go-librespot[31338]: time="2026-09-25T04:16:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:00 volumio go-librespot[31338]: time="2026-09-25T04:16:00+01: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" Sep 25 04:16:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:00 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:00 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031889. Sep 25 04:16:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:03 volumio go-librespot[31346]: go-librespot daemon starting... Sep 25 04:16:03 volumio go-librespot[31347]: time="2026-09-25T04:16:03+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:03 volumio go-librespot[31347]: time="2026-09-25T04:16:03+01:00" level=debug msg="app state loaded" Sep 25 04:16:03 volumio go-librespot[31347]: time="2026-09-25T04:16:03+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:03 volumio go-librespot[31347]: time="2026-09-25T04:16:03+01: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" Sep 25 04:16:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:03 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:03 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031890. Sep 25 04:16:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:06 volumio go-librespot[31355]: go-librespot daemon starting... Sep 25 04:16:06 volumio go-librespot[31356]: time="2026-09-25T04:16:06+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:06 volumio go-librespot[31356]: time="2026-09-25T04:16:06+01:00" level=debug msg="app state loaded" Sep 25 04:16:06 volumio go-librespot[31356]: time="2026-09-25T04:16:06+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:06 volumio go-librespot[31356]: time="2026-09-25T04:16:06+01: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" Sep 25 04:16:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:06 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:06 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:09 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:09 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031891. Sep 25 04:16:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:10 volumio go-librespot[31393]: go-librespot daemon starting... Sep 25 04:16:10 volumio go-librespot[31394]: time="2026-09-25T04:16:10+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:10 volumio go-librespot[31394]: time="2026-09-25T04:16:10+01:00" level=debug msg="app state loaded" Sep 25 04:16:10 volumio go-librespot[31394]: time="2026-09-25T04:16:10+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:10 volumio go-librespot[31394]: time="2026-09-25T04:16:10+01: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" Sep 25 04:16:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:12 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:12 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031892. Sep 25 04:16:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:13 volumio go-librespot[31404]: go-librespot daemon starting... Sep 25 04:16:13 volumio go-librespot[31405]: time="2026-09-25T04:16:13+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:13 volumio go-librespot[31405]: time="2026-09-25T04:16:13+01:00" level=debug msg="app state loaded" Sep 25 04:16:13 volumio go-librespot[31405]: time="2026-09-25T04:16:13+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:13 volumio go-librespot[31405]: time="2026-09-25T04:16:13+01: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" Sep 25 04:16:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:15 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:15 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031893. Sep 25 04:16:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:16 volumio go-librespot[31415]: go-librespot daemon starting... Sep 25 04:16:16 volumio go-librespot[31416]: time="2026-09-25T04:16:16+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:16 volumio go-librespot[31416]: time="2026-09-25T04:16:16+01:00" level=debug msg="app state loaded" Sep 25 04:16:16 volumio go-librespot[31416]: time="2026-09-25T04:16:16+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:16 volumio go-librespot[31416]: time="2026-09-25T04:16:16+01: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" Sep 25 04:16:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:18 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:18 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031894. Sep 25 04:16:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:19 volumio go-librespot[31438]: go-librespot daemon starting... Sep 25 04:16:19 volumio go-librespot[31439]: time="2026-09-25T04:16:19+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:19 volumio go-librespot[31439]: time="2026-09-25T04:16:19+01:00" level=debug msg="app state loaded" Sep 25 04:16:19 volumio go-librespot[31439]: time="2026-09-25T04:16:19+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:19 volumio go-librespot[31439]: time="2026-09-25T04:16:19+01: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" Sep 25 04:16:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:21 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:21 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:22 volumio bluealsa[1019]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_7D_A1_86_2B_BF_84, ...) Sep 25 04:16:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031895. Sep 25 04:16:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:23 volumio go-librespot[31448]: go-librespot daemon starting... Sep 25 04:16:23 volumio go-librespot[31449]: time="2026-09-25T04:16:23+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:23 volumio go-librespot[31449]: time="2026-09-25T04:16:23+01:00" level=debug msg="app state loaded" Sep 25 04:16:23 volumio go-librespot[31449]: time="2026-09-25T04:16:23+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:23 volumio go-librespot[31449]: time="2026-09-25T04:16:23+01: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" Sep 25 04:16:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:24 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:24 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:25 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:25.116+01:00 level=INFO msg="new address was allocated" component=ble/conn old=1 new=2 Sep 25 04:16:25 volumio dbus-daemon[700]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.264" (uid=0 pid=32299 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.4" (uid=0 pid=880 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Sep 25 04:16:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:26.064+01:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="00:00:00:00:00:00%01 @ 0x33ccd20" latency=-389h28m12.802772656s platform=PLATFORM_ANDROID version=6.260930.0 Sep 25 04:16:26 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:16:26 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:16:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031896. Sep 25 04:16:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:26.243+01:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="00:00:00:00:00:00%01 @ 0x33ccd20" latency=-389h28m13.381341646s timeout=20s Sep 25 04:16:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:26.244+01:00 level=INFO msg="emitting device capabilities changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" Sep 25 04:16:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:26 volumio go-librespot[31457]: go-librespot daemon starting... Sep 25 04:16:26 volumio go-librespot[31458]: time="2026-09-25T04:16:26+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:26 volumio go-librespot[31458]: time="2026-09-25T04:16:26+01:00" level=debug msg="app state loaded" Sep 25 04:16:26 volumio volumio[31133]: info: Received Get System Info Sep 25 04:16:26 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:16:26 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:16:26 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:16:26 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:16:26 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:16:26 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:16:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:26.350+01:00 level=INFO msg="emitting device name changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" name=Volumio Sep 25 04:16:26 volumio go-librespot[31458]: time="2026-09-25T04:16:26+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:26 volumio go-librespot[31458]: time="2026-09-25T04:16:26+01: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" Sep 25 04:16:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:26.430+01:00 level=INFO msg="emitting device language changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" language=en Sep 25 04:16:26 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Sep 25 04:16:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:26.516+01:00 level=INFO msg="emitting device timezone changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" timezone=Europe/London Sep 25 04:16:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:26.603+01:00 level=INFO msg="emitting ethernet info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=false macAddress= ip4Address= ip6Address= Sep 25 04:16:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:26.693+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Sep 25 04:16:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:26.827+01:00 level=INFO msg="emitting device setup status changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" setupComplete=true Sep 25 04:16:26 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Sep 25 04:16:26 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Sep 25 04:16:27 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 25 04:16:27 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Sep 25 04:16:27 volumio volumio[31133]: amixer -c 3 info | grep "snd_rpi_hifiberry_dacplus" Sep 25 04:16:27 volumio volumio[31133]: Card sysdefault:3 'sndrpihifiberry'/'snd_rpi_hifiberry_dacplus' Sep 25 04:16:27 volumio volumio[31133]: amixer -c 0 info | grep "bcm2835 ALSA" Sep 25 04:16:27 volumio volumio[31133]: amixer -c 1 info | grep "bcm2835 Headphones" Sep 25 04:16:27 volumio volumio[31133]: Card sysdefault:1 'Headphones'/'bcm2835 Headphones' Sep 25 04:16:27 volumio volumio[31133]: amixer -c 3 info | grep "snd_rpi_hifiberry_dacplus" Sep 25 04:16:27 volumio volumio[31133]: Card sysdefault:3 'sndrpihifiberry'/'snd_rpi_hifiberry_dacplus' Sep 25 04:16:27 volumio volumio[31133]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 2 Sep 25 04:16:27 volumio volumio[31133]: /bin/sh: 1: /usr/local/bin/alsacap: not found Sep 25 04:16:27 volumio volumio[31133]: {"cmd":"/usr/local/bin/alsacap -C 2","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 2\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Sep 25 04:16:27 volumio volumio[31133]: amixer -c 2 info | grep "vc4-hdmi" Sep 25 04:16:27 volumio volumio[31133]: Card sysdefault:2 'vc4hdmi'/'vc4-hdmi' Sep 25 04:16:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:27.177+01:00 level=INFO msg="emitting audio outputs changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" selectedOutputId=3 Sep 25 04:16:27 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:16:27 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:16:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:27.241+01:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" state=STATUS_STOPPED positionMs=0 volume=51 Sep 25 04:16:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:27.322+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" id="mnt/NAS/NAS/lossy/B/Basement Jaxx/Kish Kash/01 Basement Jaxx feat. Lisa Kekaula - Good Luck.wma" title="Good Luck (feat. Lisa Kekaula)" Sep 25 04:16:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:27.593+01:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="00:00:00:00:00:00%01 @ 0x33ccd20" latency=-389h28m13.386375352s timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_SETUP_V1_INTERNET Sep 25 04:16:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:27.772+01:00 level=INFO msg="run WiFi scan" component=server type=REQUEST_TYPE_RUN_WIFI_SCAN peer="00:00:00:00:00:00%01 @ 0x33ccd20" latency=-389h28m13.424324656s timeout=1m0s Sep 25 04:16:27 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:27 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:28 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:28.881+01:00 level=INFO msg="emitting wifi scan event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" networks=6 Sep 25 04:16:29 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:29.385+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Sep 25 04:16:29 volumio volumio[31133]: info: Received Get System Info Sep 25 04:16:29 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:16:29 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:16:29 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:16:29 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:16:29 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:16:29 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:16:29 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:16:29 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:16:29 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:29 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Sep 25 04:16:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031897. Sep 25 04:16:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:29 volumio go-librespot[31493]: go-librespot daemon starting... Sep 25 04:16:29 volumio go-librespot[31494]: time="2026-09-25T04:16:29+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:29 volumio go-librespot[31494]: time="2026-09-25T04:16:29+01:00" level=debug msg="app state loaded" Sep 25 04:16:29 volumio go-librespot[31494]: time="2026-09-25T04:16:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:29 volumio go-librespot[31494]: time="2026-09-25T04:16:29+01: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" Sep 25 04:16:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:30 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:30.377+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:16:30 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:30 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031898. Sep 25 04:16:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:32 volumio go-librespot[31516]: go-librespot daemon starting... Sep 25 04:16:32 volumio go-librespot[31517]: time="2026-09-25T04:16:32+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:32 volumio go-librespot[31517]: time="2026-09-25T04:16:32+01:00" level=debug msg="app state loaded" Sep 25 04:16:32 volumio go-librespot[31517]: time="2026-09-25T04:16:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:32 volumio go-librespot[31517]: time="2026-09-25T04:16:32+01: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" Sep 25 04:16:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:33 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:33 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031899. Sep 25 04:16:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:36 volumio go-librespot[31525]: go-librespot daemon starting... Sep 25 04:16:36 volumio go-librespot[31526]: time="2026-09-25T04:16:36+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:36 volumio go-librespot[31526]: time="2026-09-25T04:16:36+01:00" level=debug msg="app state loaded" Sep 25 04:16:36 volumio go-librespot[31526]: time="2026-09-25T04:16:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:36 volumio go-librespot[31526]: time="2026-09-25T04:16:36+01: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" Sep 25 04:16:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:36 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:36 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031900. Sep 25 04:16:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:39 volumio go-librespot[31534]: go-librespot daemon starting... Sep 25 04:16:39 volumio go-librespot[31535]: time="2026-09-25T04:16:39+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:39 volumio go-librespot[31535]: time="2026-09-25T04:16:39+01:00" level=debug msg="app state loaded" Sep 25 04:16:39 volumio go-librespot[31535]: time="2026-09-25T04:16:39+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:39 volumio go-librespot[31535]: time="2026-09-25T04:16:39+01: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" Sep 25 04:16:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:39 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:39 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:40 volumio bluealsa[1019]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7F_DC_45_1F_7F_E4, ...) Sep 25 04:16:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031901. Sep 25 04:16:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:42 volumio go-librespot[31557]: go-librespot daemon starting... Sep 25 04:16:42 volumio go-librespot[31558]: time="2026-09-25T04:16:42+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:42 volumio go-librespot[31558]: time="2026-09-25T04:16:42+01:00" level=debug msg="app state loaded" Sep 25 04:16:42 volumio go-librespot[31558]: time="2026-09-25T04:16:42+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:42 volumio go-librespot[31558]: time="2026-09-25T04:16:42+01: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" Sep 25 04:16:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:42 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:42.758+01:00 level=INFO msg="run WiFi scan" component=server type=REQUEST_TYPE_RUN_WIFI_SCAN peer="00:00:00:00:00:00%01 @ 0x33ccd20" latency=-389h28m13.450011441s timeout=1m0s Sep 25 04:16:42 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:42 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:43 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:43.871+01:00 level=INFO msg="emitting wifi scan event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" networks=12 Sep 25 04:16:44 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:44.384+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Sep 25 04:16:44 volumio volumio[31133]: info: Received Get System Info Sep 25 04:16:44 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:16:44 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:16:44 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:16:44 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:16:44 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:16:44 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:16:44 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:16:44 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:16:44 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 44575. Sep 25 04:16:44 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Sep 25 04:16:44 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Sep 25 04:16:45 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:45.367+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:16:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031902. Sep 25 04:16:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:45 volumio go-librespot[31574]: go-librespot daemon starting... Sep 25 04:16:45 volumio go-librespot[31575]: time="2026-09-25T04:16:45+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:45 volumio go-librespot[31575]: time="2026-09-25T04:16:45+01:00" level=debug msg="app state loaded" Sep 25 04:16:45 volumio go-librespot[31575]: time="2026-09-25T04:16:45+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:45 volumio go-librespot[31575]: time="2026-09-25T04:16:45+01: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" Sep 25 04:16:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:45 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:45 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:47 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:47.483+01:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="00:00:00:00:00:00%01 @ 0x33ccd20" latency=-389h28m13.468047204s timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_SETUP_V1_INTERNET Sep 25 04:16:47 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:47.663+01:00 level=INFO msg="run WiFi scan" component=server type=REQUEST_TYPE_RUN_WIFI_SCAN peer="00:00:00:00:00:00%01 @ 0x33ccd20" latency=-389h28m13.404041976s timeout=1m0s Sep 25 04:16:48 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:48.790+01:00 level=INFO msg="emitting wifi scan event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" networks=12 Sep 25 04:16:48 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:48 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031903. Sep 25 04:16:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:49 volumio go-librespot[31584]: go-librespot daemon starting... Sep 25 04:16:49 volumio go-librespot[31585]: time="2026-09-25T04:16:49+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:49 volumio go-librespot[31585]: time="2026-09-25T04:16:49+01:00" level=debug msg="app state loaded" Sep 25 04:16:49 volumio go-librespot[31585]: time="2026-09-25T04:16:49+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:49 volumio go-librespot[31585]: time="2026-09-25T04:16:49+01: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" Sep 25 04:16:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:49 volumio volumio[31133]: info: Received Get System Info Sep 25 04:16:49 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:16:49 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:16:49 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:16:49 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:16:49 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:16:49 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:16:49 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:16:49 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:16:49 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:49.308+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Sep 25 04:16:50 volumio volumio5-onboarding[32299]: time=2026-09-25T04:16:50.281+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:16:51 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:51 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031904. Sep 25 04:16:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:52 volumio go-librespot[31608]: go-librespot daemon starting... Sep 25 04:16:52 volumio go-librespot[31609]: time="2026-09-25T04:16:52+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:52 volumio go-librespot[31609]: time="2026-09-25T04:16:52+01:00" level=debug msg="app state loaded" Sep 25 04:16:52 volumio go-librespot[31609]: time="2026-09-25T04:16:52+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:52 volumio go-librespot[31609]: time="2026-09-25T04:16:52+01: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" Sep 25 04:16:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:54 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:54 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031905. Sep 25 04:16:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:55 volumio go-librespot[31617]: go-librespot daemon starting... Sep 25 04:16:55 volumio go-librespot[31618]: time="2026-09-25T04:16:55+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:55 volumio go-librespot[31618]: time="2026-09-25T04:16:55+01:00" level=debug msg="app state loaded" Sep 25 04:16:55 volumio go-librespot[31618]: time="2026-09-25T04:16:55+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:55 volumio go-librespot[31618]: time="2026-09-25T04:16:55+01: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" Sep 25 04:16:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:16:57 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:16:57 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:16:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031906. Sep 25 04:16:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:16:58 volumio go-librespot[31626]: go-librespot daemon starting... Sep 25 04:16:58 volumio go-librespot[31627]: time="2026-09-25T04:16:58+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:16:58 volumio go-librespot[31627]: time="2026-09-25T04:16:58+01:00" level=debug msg="app state loaded" Sep 25 04:16:58 volumio go-librespot[31627]: time="2026-09-25T04:16:58+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:16:58 volumio go-librespot[31627]: time="2026-09-25T04:16:58+01: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" Sep 25 04:16:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:16:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:17:00 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:17:00 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:17:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031907. Sep 25 04:17:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:02 volumio go-librespot[31650]: go-librespot daemon starting... Sep 25 04:17:02 volumio go-librespot[31651]: time="2026-09-25T04:17:02+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:17:02 volumio go-librespot[31651]: time="2026-09-25T04:17:02+01:00" level=debug msg="app state loaded" Sep 25 04:17:02 volumio go-librespot[31651]: time="2026-09-25T04:17:02+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:17:02 volumio go-librespot[31651]: time="2026-09-25T04:17:02+01: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" Sep 25 04:17:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:17:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:17:03 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:17:03 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:17:05 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:05.079+01:00 level=INFO msg="connect to WiFi" component=server type=REQUEST_TYPE_CONNECT_TO_WIFI peer="00:00:00:00:00:00%01 @ 0x33ccd20" latency=-389h28m13.46007954s timeout=1m0s ssid=OhBasYouBarkinBarSteward Sep 25 04:17:05 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:05.080+01:00 level=INFO msg="wpa_supplicant control socket not functional, starting temporary daemon" component=volumio reason="dial unixgram /tmp/wpa_supplicant2400646349->/var/run/wpa_supplicant/wlan0: connect: no such file or directory" Sep 25 04:17:05 volumio wpa_supplicant[31660]: Successfully initialized wpa_supplicant Sep 25 04:17:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031908. Sep 25 04:17:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:05 volumio go-librespot[31661]: go-librespot daemon starting... Sep 25 04:17:05 volumio go-librespot[31662]: time="2026-09-25T04:17:05+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:17:05 volumio go-librespot[31662]: time="2026-09-25T04:17:05+01:00" level=debug msg="app state loaded" Sep 25 04:17:05 volumio go-librespot[31662]: time="2026-09-25T04:17:05+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:17:05 volumio go-librespot[31662]: time="2026-09-25T04:17:05+01: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" Sep 25 04:17:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:17:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:17:05 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:05.633+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Sep 25 04:17:05 volumio volumio[31133]: info: Received Get System Info Sep 25 04:17:05 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:17:05 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:17:05 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:17:05 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:05 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:05 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:17:05 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:17:05 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:17:06 volumio wpa_supplicant[31660]: wlan0: SME: Trying to authenticate with 96:30:66:98:cb:1e (SSID='OhBasYouBarkinBarSteward' freq=2437 MHz) Sep 25 04:17:06 volumio kernel: wlan0: authenticate with 96:30:66:98:cb:1e (local address=40:a5:ef:07:12:1a) Sep 25 04:17:06 volumio kernel: wlan0: send auth to 96:30:66:98:cb:1e (try 1/3) Sep 25 04:17:06 volumio wpa_supplicant[31660]: wlan0: Trying to associate with 96:30:66:98:cb:1e (SSID='OhBasYouBarkinBarSteward' freq=2437 MHz) Sep 25 04:17:06 volumio kernel: wlan0: authenticated Sep 25 04:17:06 volumio kernel: wlan0: associate with 96:30:66:98:cb:1e (try 1/3) Sep 25 04:17:06 volumio wpa_supplicant[31660]: wlan0: Associated with 96:30:66:98:cb:1e Sep 25 04:17:06 volumio wpa_supplicant[31660]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Sep 25 04:17:06 volumio kernel: wlan0: RX AssocResp from 96:30:66:98:cb:1e (capab=0x1431 status=0 aid=2) Sep 25 04:17:06 volumio kernel: wlan0: associated Sep 25 04:17:06 volumio wpa_supplicant[31660]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=GB Sep 25 04:17:06 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:06.525+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:17:06 volumio kernel: wlan0: Limiting TX power to 20 (20 - 0) dBm as advertised by 96:30:66:98:cb:1e Sep 25 04:17:06 volumio wpa_supplicant[31660]: wlan0: WPA: Key negotiation completed with 96:30:66:98:cb:1e [PTK=CCMP GTK=CCMP] Sep 25 04:17:06 volumio wpa_supplicant[31660]: wlan0: CTRL-EVENT-CONNECTED - Connection to 96:30:66:98:cb:1e completed [id=0 id_str=] Sep 25 04:17:06 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:06.689+01:00 level=INFO msg="connected temporarily to WiFi network" component=volumio ssid=OhBasYouBarkinBarSteward Sep 25 04:17:06 volumio dhcpcd[743]: wlan0: carrier acquired Sep 25 04:17:06 volumio dhcpcd[743]: wlan0: connected to Access Point: OhBasYouBarkinBarSteward Sep 25 04:17:06 volumio wpa_supplicant[31660]: wlan0: RRM: Unexpected neighbor report Sep 25 04:17:06 volumio kernel: wlan0: deauthenticating from 96:30:66:98:cb:1e by local choice (Reason: 3=DEAUTH_LEAVING) Sep 25 04:17:06 volumio dhcpcd[743]: wlan0: IAID ef:07:12:1a Sep 25 04:17:06 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:17:06 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:17:06 volumio wpa_supplicant[31660]: wlan0: CTRL-EVENT-DISCONNECTED bssid=96:30:66:98:cb:1e reason=3 locally_generated=1 Sep 25 04:17:06 volumio dhcpcd[743]: wlan0: carrier lost Sep 25 04:17:07 volumio wpa_supplicant[31660]: wlan0: CTRL-EVENT-DSCP-POLICY clear_all Sep 25 04:17:07 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , saveWirelessNetworkSettings Sep 25 04:17:07 volumio volumio[31133]: info: Saving new wireless network Sep 25 04:17:07 volumio sudo[31688]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/wpa_supplicant/wpa_supplicant.conf Sep 25 04:17:07 volumio sudo[31688]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:07 volumio sudo[31688]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:07 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , onNetworkingRestart Sep 25 04:17:07 volumio sudo[31691]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart wireless.service Sep 25 04:17:07 volumio sudo[31691]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:07 volumio systemd[1]: Stopping wireless.service - Wireless Services... Sep 25 04:17:07 volumio systemd[1]: wireless.service: Deactivated successfully. Sep 25 04:17:07 volumio systemd[1]: Stopped wireless.service - Wireless Services. Sep 25 04:17:07 volumio systemd[1]: wireless.service: Consumed 8min 53.265s CPU time. Sep 25 04:17:07 volumio systemd[1]: Starting wireless.service - Wireless Services... Sep 25 04:17:08 volumio volumio[31133]: info: Received Get System Info Sep 25 04:17:08 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:17:08 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:17:08 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:17:08 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:08 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:08 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:17:08 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:08.018+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Sep 25 04:17:08 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:17:08 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:17:08 volumio wireless.js[31697]: WIRELESS.JS - INFO: Single Network Mode enabled (default) - only one network device can be active at a time between ethernet and wireless Sep 25 04:17:08 volumio wireless.js[31697]: WIRELESS.JS - INFO: Wireless.js initializing wireless flow Sep 25 04:17:08 volumio sudo[31719]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:08 volumio sudo[31719]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:08 volumio sudo[31719]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031909. Sep 25 04:17:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:08 volumio sudo[31724]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Sep 25 04:17:08 volumio sudo[31724]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:08 volumio sudo[31724]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:08 volumio sudo[31727]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Sep 25 04:17:08 volumio sudo[31727]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:08 volumio go-librespot[31725]: go-librespot daemon starting... Sep 25 04:17:08 volumio go-librespot[31729]: time="2026-09-25T04:17:08+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:17:08 volumio go-librespot[31729]: time="2026-09-25T04:17:08+01:00" level=debug msg="app state loaded" Sep 25 04:17:08 volumio sudo[31727]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:08 volumio wireless.js[31697]: WIRELESS.JS - INFO: Cleaning previous... Sep 25 04:17:08 volumio go-librespot[31729]: time="2026-09-25T04:17:08+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:17:08 volumio go-librespot[31729]: time="2026-09-25T04:17:08+01: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" Sep 25 04:17:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:17:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:17:08 volumio sudo[31738]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Sep 25 04:17:08 volumio sudo[31738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:08 volumio sudo[31738]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:08 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:08.901+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:17:08 volumio wireless.js[31697]: WIRELESS.JS - INFO: InterfaceValidator: READY - wlan0 is ready for operations Sep 25 04:17:08 volumio wireless.js[31697]: WIRELESS.JS - INFO: InterfaceValidator: wlan0 became ready after 3ms Sep 25 04:17:08 volumio wireless.js[31697]: WIRELESS.JS - INFO: ensureInterfaceReady: Interface ready (MAC: 40:a5:ef:07:12:1a) Sep 25 04:17:09 volumio sudo[31746]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Sep 25 04:17:09 volumio sudo[31746]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:09 volumio sudo[31746]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:09 volumio sudo[31755]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Sep 25 04:17:09 volumio sudo[31755]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:09 volumio sudo[31760]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:09 volumio sudo[31760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:09 volumio sudo[31760]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:09 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:09.408+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Sep 25 04:17:09 volumio volumio[31133]: info: Received Get System Info Sep 25 04:17:09 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:17:09 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:17:09 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:17:09 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:09 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:09 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:17:09 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:17:09 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:17:09 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:17:10 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:17:10 volumio sudo[31777]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:10 volumio sudo[31777]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:10 volumio sudo[31777]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:10 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:10.289+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:17:10 volumio sudo[31755]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:10 volumio wireless.js[31697]: WIRELESS.JS - INFO: Regdomain already correct: GB Sep 25 04:17:10 volumio wireless.js[31697]: WIRELESS.JS - INFO: Start wireless flow Sep 25 04:17:10 volumio wireless.js[31697]: WIRELESS.JS - INFO: Stopped hotspot (if there).. Sep 25 04:17:10 volumio sudo[31783]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Sep 25 04:17:10 volumio sudo[31783]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:10 volumio sudo[31783]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:10 volumio sudo[31785]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Sep 25 04:17:10 volumio sudo[31785]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:10 volumio sudo[31785]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:10 volumio wireless.js[31697]: WIRELESS.JS - INFO: InterfaceValidator: READY - wlan0 is ready for operations Sep 25 04:17:10 volumio wireless.js[31697]: WIRELESS.JS - INFO: STAGE 1: wlan0 validated and ready (MAC: 40:a5:ef:07:12:1a, USB: true) Sep 25 04:17:10 volumio wpa_supplicant[31791]: Successfully initialized wpa_supplicant Sep 25 04:17:10 volumio sudo[31795]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Sep 25 04:17:10 volumio sudo[31795]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:10 volumio sudo[31795]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:11 volumio sudo[31801]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:11 volumio sudo[31801]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:11 volumio sudo[31801]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:11 volumio volumio[31133]: info: Received Get System Info Sep 25 04:17:11 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:17:11 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:17:11 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:17:11 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:11 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:11 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:17:11 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:11.297+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Sep 25 04:17:11 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:17:11 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:17:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031910. Sep 25 04:17:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:11 volumio go-librespot[31803]: go-librespot daemon starting... Sep 25 04:17:11 volumio go-librespot[31804]: time="2026-09-25T04:17:11+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:17:11 volumio go-librespot[31804]: time="2026-09-25T04:17:11+01:00" level=debug msg="app state loaded" Sep 25 04:17:11 volumio go-librespot[31804]: time="2026-09-25T04:17:11+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:17:11 volumio go-librespot[31804]: time="2026-09-25T04:17:11+01: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" Sep 25 04:17:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:17:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:17:11 volumio wireless.js[31697]: WIRELESS.JS - INFO: DHCP IP fallback Sep 25 04:17:11 volumio wireless.js[31697]: WIRELESS.JS - INFO: STAGE 2: Starting event-driven WPA state monitor Sep 25 04:17:11 volumio wireless.js[31697]: WIRELESS.JS - INFO: WpaStateMachine: Starting state monitor for wlan0 Sep 25 04:17:12 volumio wpa_supplicant[31792]: wlan0: SME: Trying to authenticate with 96:30:66:98:cb:1e (SSID='OhBasYouBarkinBarSteward' freq=2437 MHz) Sep 25 04:17:12 volumio kernel: wlan0: authenticate with 96:30:66:98:cb:1e (local address=40:a5:ef:07:12:1a) Sep 25 04:17:12 volumio kernel: wlan0: send auth to 96:30:66:98:cb:1e (try 1/3) Sep 25 04:17:12 volumio wpa_supplicant[31792]: wlan0: Trying to associate with 96:30:66:98:cb:1e (SSID='OhBasYouBarkinBarSteward' freq=2437 MHz) Sep 25 04:17:12 volumio kernel: wlan0: authenticated Sep 25 04:17:12 volumio kernel: wlan0: associate with 96:30:66:98:cb:1e (try 1/3) Sep 25 04:17:12 volumio kernel: wlan0: RX AssocResp from 96:30:66:98:cb:1e (capab=0x1431 status=0 aid=2) Sep 25 04:17:12 volumio wpa_supplicant[31792]: wlan0: Associated with 96:30:66:98:cb:1e Sep 25 04:17:12 volumio wpa_supplicant[31792]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Sep 25 04:17:12 volumio wpa_supplicant[31792]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=GB Sep 25 04:17:12 volumio kernel: wlan0: associated Sep 25 04:17:12 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:12.175+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:17:12 volumio kernel: wlan0: Limiting TX power to 20 (20 - 0) dBm as advertised by 96:30:66:98:cb:1e Sep 25 04:17:12 volumio sudo[31817]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:12 volumio sudo[31817]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:12 volumio sudo[31817]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:12 volumio wireless.js[31697]: WIRELESS.JS - INFO: WpaStateMachine: State transition: NULL -> 4WAY_HANDSHAKE (duration: 0ms) Sep 25 04:17:12 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:12.616+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=true macAddress=40:a5:ef:07:12:1a ip4Address= ip6Address= ssid=OhBasYouBarkinBarSteward Sep 25 04:17:12 volumio volumio[31133]: info: Received Get System Info Sep 25 04:17:12 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:17:12 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:17:12 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:17:12 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:12 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:12 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:17:12 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:17:12 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:17:13 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:17:13 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:17:13 volumio sudo[31826]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:13 volumio sudo[31826]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:13 volumio sudo[31826]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:13 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:13.496+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:17:14 volumio sudo[31835]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:14 volumio sudo[31835]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:14 volumio sudo[31835]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031911. Sep 25 04:17:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:15 volumio go-librespot[31843]: go-librespot daemon starting... Sep 25 04:17:15 volumio go-librespot[31844]: time="2026-09-25T04:17:15+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:17:15 volumio go-librespot[31844]: time="2026-09-25T04:17:15+01:00" level=debug msg="app state loaded" Sep 25 04:17:15 volumio go-librespot[31844]: time="2026-09-25T04:17:15+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:17:15 volumio go-librespot[31844]: time="2026-09-25T04:17:15+01: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" Sep 25 04:17:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:17:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:17:15 volumio sudo[31853]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:15 volumio sudo[31853]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:15 volumio sudo[31853]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:16 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:17:16 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:17:16 volumio dhcpcd[743]: wlan0: carrier lost Sep 25 04:17:16 volumio kernel: wlan0: deauthenticated from 96:30:66:98:cb:1e (Reason: 15=4WAY_HANDSHAKE_TIMEOUT) Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: CTRL-EVENT-DISCONNECTED bssid=96:30:66:98:cb:1e reason=15 Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: WPA: 4-Way Handshake failed - pre-shared key may be incorrect Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="OhBasYouBarkinBarSteward" auth_failures=1 duration=10 reason=WRONG_KEY Sep 25 04:17:16 volumio wpa_supplicant[31792]: BSSID 96:30:66:98:cb:1e ignore list count incremented to 2, ignoring for 10 seconds Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=GB Sep 25 04:17:16 volumio sudo[31869]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:16 volumio sudo[31869]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:16 volumio sudo[31869]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: SME: Trying to authenticate with 92:30:66:98:cb:1e (SSID='UX7' freq=2437 MHz) Sep 25 04:17:16 volumio kernel: wlan0: authenticate with 92:30:66:98:cb:1e (local address=40:a5:ef:07:12:1a) Sep 25 04:17:16 volumio kernel: wlan0: send auth to 92:30:66:98:cb:1e (try 1/3) Sep 25 04:17:16 volumio wireless.js[31697]: WIRELESS.JS - INFO: WpaStateMachine: State transition: 4WAY_HANDSHAKE -> AUTHENTICATING (duration: 4087ms) Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: Trying to associate with 92:30:66:98:cb:1e (SSID='UX7' freq=2437 MHz) Sep 25 04:17:16 volumio kernel: wlan0: authenticated Sep 25 04:17:16 volumio kernel: wlan0: associate with 92:30:66:98:cb:1e (try 1/3) Sep 25 04:17:16 volumio kernel: wlan0: RX AssocResp from 92:30:66:98:cb:1e (capab=0x1431 status=0 aid=1) Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: Associated with 92:30:66:98:cb:1e Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=GB Sep 25 04:17:16 volumio kernel: wlan0: associated Sep 25 04:17:16 volumio kernel: wlan0: Limiting TX power to 20 (20 - 0) dBm as advertised by 92:30:66:98:cb:1e Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: WPA: Key negotiation completed with 92:30:66:98:cb:1e [PTK=CCMP GTK=CCMP] Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: CTRL-EVENT-CONNECTED - Connection to 92:30:66:98:cb:1e completed [id=1 id_str=] Sep 25 04:17:16 volumio wpa_supplicant[31792]: wlan0: RRM: Unexpected neighbor report Sep 25 04:17:16 volumio dhcpcd[743]: wlan0: carrier acquired Sep 25 04:17:16 volumio dhcpcd[743]: wlan0: connected to Access Point: UX7 Sep 25 04:17:16 volumio dhcpcd[743]: wlan0: IAID ef:07:12:1a Sep 25 04:17:16 volumio dhcpcd[743]: wlan0: soliciting a DHCP lease Sep 25 04:17:16 volumio dhcpcd[743]: wlan0: soliciting an IPv6 router Sep 25 04:17:17 volumio dhcpcd[743]: wlan0: offered 192.168.0.186 from 192.168.0.1 Sep 25 04:17:17 volumio wireless.js[31697]: WIRELESS.JS - INFO: WpaStateMachine: State transition: AUTHENTICATING -> COMPLETED (duration: 513ms) Sep 25 04:17:17 volumio wireless.js[31697]: WIRELESS.JS - INFO: WpaStateMachine: COMPLETED - connection successful Sep 25 04:17:17 volumio wireless.js[31697]: WIRELESS.JS - INFO: STAGE 2: Connection successful - Connected to 92:30:66:98:cb:1e Sep 25 04:17:17 volumio dhcpcd[743]: wlan0: probing address 192.168.0.186/24 Sep 25 04:17:17 volumio wireless.js[31697]: WIRELESS.JS - INFO: USB WiFi Capabilities: Sep 25 04:17:17 volumio wireless.js[31697]: WIRELESS.JS - INFO: Chipset: 1-1.4:1.0 Sep 25 04:17:17 volumio wireless.js[31697]: WIRELESS.JS - INFO: AP mode: Yes Sep 25 04:17:17 volumio wireless.js[31697]: WIRELESS.JS - INFO: Concurrent: No Sep 25 04:17:17 volumio wireless.js[31697]: WIRELESS.JS - INFO: Restarting dhcpcd.service for reliable DHCP Sep 25 04:17:17 volumio sudo[31899]: root : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart dhcpcd.service Sep 25 04:17:17 volumio sudo[31899]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:17 volumio volumio[31133]: info: Received Get System Info Sep 25 04:17:17 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:17:17 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:17:17 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:17.229+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=true macAddress=40:a5:ef:07:12:1a ip4Address= ip6Address= ssid=UX7 Sep 25 04:17:17 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:17:17 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:17 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:17 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:17:17 volumio volumio[31133]: info: Discovery: Networking Restart detected, restarting advertisement and browsing Sep 25 04:17:17 volumio volumio[31133]: info: Discovery: Restarting Advertising Sep 25 04:17:17 volumio systemd[1]: Stopping dhcpcd.service - DHCP Client Daemon on all interfaces... Sep 25 04:17:17 volumio volumio[31133]: info: Discovery: Stopping existing advertisement Sep 25 04:17:17 volumio volumio[31133]: info: Discovery: Restarting Browsing Sep 25 04:17:17 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:17:17 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:17:17 volumio sudo[31903]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:17 volumio sudo[31903]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:17 volumio sudo[31903]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:17 volumio dhcpcd[31901]: sending signal TERM to pid 742 Sep 25 04:17:17 volumio dhcpcd[31901]: sending signal TERM to pid 742 Sep 25 04:17:17 volumio dhcpcd[31901]: waiting for pid 742 to exit Sep 25 04:17:17 volumio dhcpcd[31901]: waiting for pid 742 to exit Sep 25 04:17:17 volumio dhcpcd[743]: received SIGTERM, stopping Sep 25 04:17:17 volumio dhcpcd[743]: wlan0: removing interface Sep 25 04:17:17 volumio dhcpcd[743]: eth0: removing interface Sep 25 04:17:17 volumio systemd[1]: dhcpcd.service: Deactivated successfully. Sep 25 04:17:17 volumio systemd[1]: Stopped dhcpcd.service - DHCP Client Daemon on all interfaces. Sep 25 04:17:17 volumio systemd[1]: Starting dhcpcd.service - DHCP Client Daemon on all interfaces... Sep 25 04:17:17 volumio dhcpcd[31907]: dhcpcd-9.4.1 starting Sep 25 04:17:17 volumio dhcpcd[31911]: dev: loaded udev Sep 25 04:17:17 volumio dhcpcd[31911]: DUID 00:01:00:01:30:df:bc:c1:40:a5:ef:07:12:1a Sep 25 04:17:17 volumio systemd[1]: Started dhcpcd.service - DHCP Client Daemon on all interfaces. Sep 25 04:17:17 volumio sudo[31899]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:17 volumio dhcpcd[31911]: wlan0: connected to Access Point: UX7 Sep 25 04:17:17 volumio dhcpcd[31911]: eth0: waiting for carrier Sep 25 04:17:17 volumio dhcpcd[31911]: wlan0: IAID ef:07:12:1a Sep 25 04:17:17 volumio dhcpcd[31911]: wlan0: adding address fe80::bea9:19a5:60dc:2cd5 Sep 25 04:17:17 volumio dhcpcd[31911]: ipv6_addaddr1: Permission denied Sep 25 04:17:18 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:18.049+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:17:18 volumio dhcpcd[31911]: wlan0: soliciting a DHCP lease Sep 25 04:17:18 volumio dhcpcd[31911]: wlan0: offered 192.168.0.186 from 192.168.0.1 Sep 25 04:17:18 volumio dhcpcd[31911]: wlan0: probing address 192.168.0.186/24 Sep 25 04:17:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031912. Sep 25 04:17:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:18 volumio volumio[31133]: info: Discovery: A device disappeared from network Sep 25 04:17:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:18 volumio go-librespot[31927]: go-librespot daemon starting... Sep 25 04:17:18 volumio sudo[31929]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:18 volumio sudo[31929]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:18 volumio sudo[31929]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:18 volumio go-librespot[31930]: time="2026-09-25T04:17:18+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:17:18 volumio go-librespot[31930]: time="2026-09-25T04:17:18+01:00" level=debug msg="app state loaded" Sep 25 04:17:18 volumio go-librespot[31930]: time="2026-09-25T04:17:18+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:17:18 volumio go-librespot[31930]: time="2026-09-25T04:17:18+01: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" Sep 25 04:17:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:17:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:17:18 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:18.381+01:00 level=INFO msg="emitting ethernet info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=false macAddress= ip4Address= ip6Address= Sep 25 04:17:18 volumio volumio[31133]: info: Received Get System Info Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:17:18 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:18 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:17:18 volumio volumio[31133]: info: Received Get System Info Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:17:18 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:18 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:17:18 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:18.392+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=true macAddress=40:a5:ef:07:12:1a ip4Address= ip6Address= ssid=UX7 Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:17:18 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:17:18 volumio dhcpcd[31911]: wlan0: soliciting an IPv6 router Sep 25 04:17:19 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:17:19 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:17:19 volumio sudo[31940]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:19 volumio sudo[31940]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:19 volumio sudo[31940]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:19 volumio wireless.js[31697]: WIRELESS.JS - INFO: Start ap Sep 25 04:17:20 volumio wireless.js[31697]: WIRELESS.JS - INFO: Notified systemd about wireless ready Sep 25 04:17:20 volumio systemd[1]: Started wireless.service - Wireless Services. Sep 25 04:17:20 volumio sudo[31691]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:20 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:20.195+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:17:20 volumio sudo[31960]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:20 volumio sudo[31960]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:20 volumio sudo[31960]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:20 volumio wireless.js[31697]: WIRELESS.JS - INFO: trying... Sep 25 04:17:21 volumio sudo[31971]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 25 04:17:21 volumio sudo[31971]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:21 volumio sudo[31971]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:21 volumio sudo[31974]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:21 volumio sudo[31974]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:21 volumio sudo[31974]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:21 volumio wireless.js[31697]: WIRELESS.JS - INFO: ... wlan0 IPv4 is undefined, ipV6 is undefined Sep 25 04:17:21 volumio sudo[31977]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:21 volumio sudo[31977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:21 volumio sudo[31977]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031913. Sep 25 04:17:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:21 volumio go-librespot[31979]: go-librespot daemon starting... Sep 25 04:17:21 volumio go-librespot[31980]: time="2026-09-25T04:17:21+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:17:21 volumio go-librespot[31980]: time="2026-09-25T04:17:21+01:00" level=debug msg="app state loaded" Sep 25 04:17:21 volumio go-librespot[31980]: time="2026-09-25T04:17:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:17:21 volumio go-librespot[31980]: time="2026-09-25T04:17:21+01: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" Sep 25 04:17:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:17:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:17:21 volumio wireless.js[31697]: WIRELESS.JS - INFO: trying... Sep 25 04:17:22 volumio sudo[31997]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 25 04:17:22 volumio sudo[31997]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:22 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:17:22 volumio sudo[31997]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:22 volumio volumio[31133]: info: Error connecting to go-librespot Websocket: AggregateError Sep 25 04:17:22 volumio sudo[32000]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:22 volumio sudo[32000]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:22 volumio sudo[32000]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:22 volumio wireless.js[31697]: WIRELESS.JS - INFO: ... wlan0 IPv4 is undefined, ipV6 is undefined Sep 25 04:17:22 volumio volumio[31133]: info: Discovery: Started advertising with name: Volumio Sep 25 04:17:22 volumio sudo[32005]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:22 volumio sudo[32005]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:22 volumio sudo[32005]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:22 volumio wireless.js[31697]: WIRELESS.JS - INFO: trying... Sep 25 04:17:23 volumio sudo[32016]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 25 04:17:23 volumio sudo[32016]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:23 volumio sudo[32016]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:23 volumio sudo[32019]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:23 volumio sudo[32019]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:23 volumio sudo[32019]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:23 volumio wireless.js[31697]: WIRELESS.JS - INFO: ... wlan0 IPv4 is undefined, ipV6 is undefined Sep 25 04:17:23 volumio volumio[31133]: info: Discovery: adding 84fd0712-c87d-49d8-971e-dff635a7d72c Sep 25 04:17:23 volumio volumio[31133]: info: Discovery: Found device Volumio Sep 25 04:17:23 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:23 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:23 volumio volumio[31133]: info: Discovery: this is already registered, 84fd0712-c87d-49d8-971e-dff635a7d72c Sep 25 04:17:23 volumio volumio[31133]: info: Discovery: Found device Volumio Sep 25 04:17:23 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:23 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:23 volumio sudo[32024]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:23 volumio sudo[32024]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:23 volumio sudo[32024]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:23 volumio dhcpcd[31911]: wlan0: leased 192.168.0.186 for 86400 seconds Sep 25 04:17:23 volumio avahi-daemon[699]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.186. Sep 25 04:17:23 volumio avahi-daemon[699]: New relevant interface wlan0.IPv4 for mDNS. Sep 25 04:17:23 volumio avahi-daemon[699]: Registering new address record for 192.168.0.186 on wlan0.IPv4. Sep 25 04:17:23 volumio dhcpcd[31911]: wlan0: adding route to 192.168.0.0/24 Sep 25 04:17:23 volumio dhcpcd[31911]: wlan0: adding default route via 192.168.0.1 Sep 25 04:17:23 volumio systemd[1]: welcome.service: Deactivated successfully. Sep 25 04:17:23 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Sep 25 04:17:23 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Sep 25 04:17:23 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Sep 25 04:17:23 volumio wireless.js[31697]: WIRELESS.JS - INFO: trying... Sep 25 04:17:23 volumio welcome[32047]: Resolved ip:[1] 192.168.0.186 Sep 25 04:17:23 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Sep 25 04:17:23 volumio systemd[1]: Reached target ip-changed@wlan0.target - IP Address changed on wlan0. Sep 25 04:17:24 volumio sudo[32063]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 25 04:17:24 volumio sudo[32063]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:24 volumio sudo[32063]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:24 volumio sudo[32066]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:24 volumio sudo[32066]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:24 volumio sudo[32066]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:24 volumio wireless.js[31697]: WIRELESS.JS - INFO: ... wlan0 IPv4 is 192.168.0.186, ipV6 is undefined Sep 25 04:17:24 volumio wireless.js[31697]: WIRELESS.JS - INFO: Connected to SSID: UX7 Sep 25 04:17:24 volumio wireless.js[31697]: WIRELESS.JS - INFO: It's done! AP Sep 25 04:17:24 volumio wireless.js[31697]: WIRELESS.JS - INFO: Restarting avahi-daemon... Sep 25 04:17:24 volumio sudo[32071]: root : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart avahi-daemon Sep 25 04:17:24 volumio sudo[32071]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 25 04:17:24 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Sep 25 04:17:24 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Sep 25 04:17:24 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 25 04:17:24 volumio systemd[1]: shairport-sync.service: Consumed 29.385s CPU time. Sep 25 04:17:24 volumio avahi-daemon[699]: Got SIGTERM, quitting. Sep 25 04:17:24 volumio systemd[1]: Stopping avahi-daemon.service - Avahi mDNS/DNS-SD Stack... Sep 25 04:17:24 volumio avahi-daemon[699]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.186. Sep 25 04:17:24 volumio avahi-daemon[699]: Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1. Sep 25 04:17:24 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:24.156+01:00 level=WARN msg="disconnected from Avahi daemon, trying to reconnect" component=discovery/localnet error="avahi: Daemon connection failed" Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Browse raised the following error Error: dns service error: unknown Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Restarting Browsing Sep 25 04:17:24 volumio avahi-daemon[699]: avahi-daemon 0.8 exiting. Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Browse raised the following error Error: dns service error: unknown Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Restarting Browsing Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Restart already pending, ignoring duplicate call Sep 25 04:17:24 volumio systemd[1]: avahi-daemon.service: Deactivated successfully. Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Browse raised the following error Error: dns service error: unknown Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Restarting Browsing Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Restart already pending, ignoring duplicate call Sep 25 04:17:24 volumio volumio[31133]: error: Discovery: Advertisement error: Error: dns service error: unknown Sep 25 04:17:24 volumio systemd[1]: Stopped avahi-daemon.service - Avahi mDNS/DNS-SD Stack. Sep 25 04:17:24 volumio volumio[31133]: error: Discovery: advertisement error: Error: dns service error: unknown Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Advertisement raised the following error Error: dns service error: unknown Sep 25 04:17:24 volumio systemd[1]: avahi-daemon.service: Consumed 28.388s CPU time. Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Stopping Advertising Immediately Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Stopping existing advertisement Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Browse raised the following error Error: dns service error: unknown Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Restarting Browsing Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Restart already pending, ignoring duplicate call Sep 25 04:17:24 volumio dbus-daemon[700]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' requested by ':1.2831' (uid=0 pid=32299 comm="/usr/bin/volumio5-onboarding") Sep 25 04:17:24 volumio systemd[1]: Starting avahi-daemon.service - Avahi mDNS/DNS-SD Stack... Sep 25 04:17:24 volumio avahi-daemon[32073]: Process 699 died: No such process; trying to remove PID file. (/run/avahi-daemon//pid) Sep 25 04:17:24 volumio avahi-daemon[32073]: Found user 'avahi' (UID 103) and group 'avahi' (GID 109). Sep 25 04:17:24 volumio avahi-daemon[32073]: Successfully dropped root privileges. Sep 25 04:17:24 volumio avahi-daemon[32073]: avahi-daemon 0.8 starting up. Sep 25 04:17:24 volumio dbus-daemon[700]: [system] Successfully activated service 'org.freedesktop.Avahi' Sep 25 04:17:24 volumio systemd[1]: Started avahi-daemon.service - Avahi mDNS/DNS-SD Stack. Sep 25 04:17:24 volumio avahi-daemon[32073]: Successfully called chroot(). Sep 25 04:17:24 volumio avahi-daemon[32073]: Successfully dropped remaining capabilities. Sep 25 04:17:24 volumio avahi-daemon[32073]: No service file found in /etc/avahi/services. Sep 25 04:17:24 volumio avahi-daemon[32073]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.186. Sep 25 04:17:24 volumio avahi-daemon[32073]: New relevant interface wlan0.IPv4 for mDNS. Sep 25 04:17:24 volumio avahi-daemon[32073]: Joining mDNS multicast group on interface lo.IPv4 with address 127.0.0.1. Sep 25 04:17:24 volumio avahi-daemon[32073]: New relevant interface lo.IPv4 for mDNS. Sep 25 04:17:24 volumio avahi-daemon[32073]: Network interface enumeration completed. Sep 25 04:17:24 volumio avahi-daemon[32073]: Registering new address record for 192.168.0.186 on wlan0.IPv4. Sep 25 04:17:24 volumio avahi-daemon[32073]: Registering new address record for 127.0.0.1 on lo.IPv4. Sep 25 04:17:24 volumio sudo[32071]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:24 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 25 04:17:24 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:24.291+01:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x33ccd20" available=true connected=true macAddress=40:a5:ef:07:12:1a ip4Address=192.168.0.186/24 ip6Address= ssid=UX7 Sep 25 04:17:24 volumio volumio[31133]: info: Received Get System Info Sep 25 04:17:24 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 25 04:17:24 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 25 04:17:24 volumio volumio[31133]: info: Discovery: Getting this device information Sep 25 04:17:24 volumio volumio[31133]: info: CoreCommandRouter::volumioGetState Sep 25 04:17:24 volumio volumio[31133]: info: CorePlayQueue::getTrack 0 Sep 25 04:17:24 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 25 04:17:24 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 25 04:17:24 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 25 04:17:24 volumio sudo[32079]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:24 volumio sudo[32079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:24 volumio wireless.js[31697]: WIRELESS.JS - INFO: Notified systemd about wireless ready Sep 25 04:17:24 volumio sudo[32079]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:24 volumio sudo[32095]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Sep 25 04:17:24 volumio sudo[32095]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:24 volumio sudo[32095]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:24 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:24.417+01:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.109:47388 Sep 25 04:17:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031914. Sep 25 04:17:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:24 volumio go-librespot[32102]: go-librespot daemon starting... Sep 25 04:17:24 volumio go-librespot[32103]: time="2026-09-25T04:17:24+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:17:24 volumio go-librespot[32103]: time="2026-09-25T04:17:24+01:00" level=debug msg="app state loaded" Sep 25 04:17:24 volumio go-librespot[32103]: time="2026-09-25T04:17:24+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:17:25 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=debug msg="new websocket client" Sep 25 04:17:25 volumio volumio[31133]: info: Connection to go-librespot Websocket established Sep 25 04:17:25 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: wizard , reportWirelessConnection Sep 25 04:17:25 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessInfo Sep 25 04:17:25 volumio sudo[32113]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:25 volumio sudo[32113]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:25 volumio sudo[32113]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:25 volumio sudo[32117]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Sep 25 04:17:25 volumio sudo[32117]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:25 volumio sudo[32117]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:25 volumio avahi-daemon[32073]: Server startup complete. Host name is volumio.local. Local service cookie is 4060645185. Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 25 04:17:25 volumio sudo[32123]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:25 volumio sudo[32123]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:25 volumio sudo[32123]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=info msg="zeroconf server listening on port 38133" Sep 25 04:17:25 volumio sudo[32127]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Sep 25 04:17:25 volumio sudo[32127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:25 volumio sudo[32127]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=debug msg="obtained new client token: AAHyD1ZIzM3TN5xAGGr7VraG/s0N6mXI4sPJYFgxpLPmbfTuRP1ZXyEIAhYE14KpSRFCoMlRCERA8FBHNB/3BQSRayUfJk+ROZn6gtOz645koUjDGqrtJQ7mnbF6QUygctnIo2VPMJDDpvabLOJJqQp+x1bRCett2BS0xOiUQGzVOlIY4+p52uOueL+OKnZapo0FIFVhbJUZKDbL9Twh31r9T4x4cASM5KH/RjgFlpykEYbB3sl9" Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=debug msg="completed keyexchange" Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=debug msg="completed challenge" Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=info msg="authenticated AP" username="a3*****************63" Sep 25 04:17:25 volumio ntpd[1002]: IO: Listen normally on 3 wlan0 192.168.0.186:123 Sep 25 04:17:25 volumio ntpd[1002]: IO: new interface(s) found: waking up resolver Sep 25 04:17:25 volumio ntpd[1002]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Sep 25 04:17:25 volumio ntpd[1002]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Sep 25 04:17:25 volumio ntpd[1002]: DNS: Pool taking: 51.89.151.183 Sep 25 04:17:25 volumio ntpd[1002]: DNS: Pool taking: 185.51.192.63 Sep 25 04:17:25 volumio ntpd[1002]: DNS: Pool taking: 91.135.3.179 Sep 25 04:17:25 volumio ntpd[1002]: DNS: Pool taking: 51.195.191.67 Sep 25 04:17:25 volumio ntpd[1002]: DNS: dns_take_status: 3.debian.pool.ntp.org=>good, 8 Sep 25 04:17:25 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:25.829+01:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s Sep 25 04:17:25 volumio go-librespot[32103]: time="2026-09-25T04:17:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 25 04:17:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:17:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:17:25 volumio volumio[31133]: info: Connection to go-librespot Websocket closed Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.030+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=http://pushupdates.volumio.org duration=196.90119ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.083+01:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Sep 25 04:17:26 volumio volumio[31133]: info: Adding plugin bluetooth to MyMusic Plugins Sep 25 04:17:26 volumio volumio[31133]: info: Adding plugin multiroom to MyMusic Plugins Sep 25 04:17:26 volumio volumio[31133]: info: Adding plugin metavolumio to MyMusic Plugins Sep 25 04:17:26 volumio volumio[31133]: info: Adding plugin cd_controller to MyMusic Plugins Sep 25 04:17:26 volumio volumio[31133]: info: Adding plugin qobuzconnect to MyMusic Plugins Sep 25 04:17:26 volumio volumio[31133]: info: Adding plugin smart_inputs to MyMusic Plugins Sep 25 04:17:26 volumio volumio[31133]: info: Adding plugin tidalconnect to MyMusic Plugins Sep 25 04:17:26 volumio volumio[31133]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.318+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=488.156393ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.387+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=https://securetoken.googleapis.com duration=555.523054ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.387+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=https://www.googleapis.com duration=552.37233ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.406+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=572.220944ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.551+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=https://google.com duration=719.2681ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.623+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=http://cddb.volumio.org duration=788.919758ms error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.700+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=http://plugins.volumio.org duration=864.1525ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.725+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=https://database.volumio.cloud duration=888.366784ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.726+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=894.510211ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.728+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=895.570261ms Sep 25 04:17:26 volumio ntpd[1002]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Sep 25 04:17:26 volumio ntpd[1002]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Sep 25 04:17:26 volumio ntpd[1002]: DNS: Pool taking: 139.143.5.30 Sep 25 04:17:26 volumio ntpd[1002]: DNS: Pool taking: 178.62.68.79 Sep 25 04:17:26 volumio ntpd[1002]: DNS: Pool taking: 82.16.107.176 Sep 25 04:17:26 volumio ntpd[1002]: DNS: Pool taking: 88.80.187.85 Sep 25 04:17:26 volumio ntpd[1002]: DNS: Pool taking: 2a10:e780:11:1::6d Sep 25 04:17:26 volumio ntpd[1002]: DNS: Pool taking: 2a01:7e00::f03c:94ff:fee2:9c69 Sep 25 04:17:26 volumio ntpd[1002]: DNS: Pool taking: 2a00:da00:f475:b00::2 Sep 25 04:17:26 volumio ntpd[1002]: DNS: Pool taking: 2a12:bec4:1821:25c::123 Sep 25 04:17:26 volumio ntpd[1002]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.773+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=https://functions.volumio.cloud duration=941.684352ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.791+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.109:47388 @ 0x35da480" latency=-389h28m13.502349354s timeout=10s endpoint=https://functions.volumio.cloud duration=955.248602ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.830+01:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.494574421s timeout=10s from=APP_PAGE_SETUP_V1_INTERNET to=APP_PAGE_LEGACY_DEVICE Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.871+01:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.913+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=40.058632ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.913+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=41.876494ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.930+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=http://pushupdates.volumio.org duration=57.511156ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.930+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=58.616832ms Sep 25 04:17:26 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:26.966+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=https://google.com duration=93.157557ms Sep 25 04:17:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:27.016+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=144.518202ms Sep 25 04:17:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:27.017+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=https://www.googleapis.com duration=145.820127ms Sep 25 04:17:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:27.034+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=https://securetoken.googleapis.com duration=162.633486ms Sep 25 04:17:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:27.080+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=https://database.volumio.cloud duration=207.048517ms Sep 25 04:17:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:27.080+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=https://functions.volumio.cloud duration=207.702891ms Sep 25 04:17:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:27.080+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=https://functions.volumio.cloud duration=207.703725ms Sep 25 04:17:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:27.179+01:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=http://cddb.volumio.org duration=307.005386ms error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Sep 25 04:17:27 volumio volumio5-onboarding[32299]: time=2026-09-25T04:17:27.280+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.0.109:47388 @ 0x33ccd20" latency=-389h28m13.506695737s timeout=10s endpoint=http://plugins.volumio.org duration=407.609128ms Sep 25 04:17:27 volumio ntpd[1002]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Sep 25 04:17:27 volumio ntpd[1002]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Sep 25 04:17:27 volumio ntpd[1002]: DNS: Pool taking: 193.57.144.50 Sep 25 04:17:27 volumio ntpd[1002]: DNS: Pool taking: 109.74.197.50 Sep 25 04:17:27 volumio ntpd[1002]: DNS: Pool skipping: 88.80.187.85 Sep 25 04:17:27 volumio ntpd[1002]: DNS: Pool taking: 85.199.214.102 Sep 25 04:17:27 volumio ntpd[1002]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Sep 25 04:17:28 volumio volumio[31133]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Sep 25 04:17:28 volumio volumio[31133]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Sep 25 04:17:28 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 25 04:17:28 volumio volumio[31133]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 25 04:17:28 volumio volumio[31133]: info: Starting MyVolumio Remote Streaming Endpoints Sep 25 04:17:28 volumio volumio[31133]: info: MyVolumio login type: Token Sep 25 04:17:28 volumio volumio[31133]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Sep 25 04:17:28 volumio volumio[31133]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Sep 25 04:17:28 volumio ntpd[1002]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Sep 25 04:17:28 volumio ntpd[1002]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Sep 25 04:17:28 volumio ntpd[1002]: DNS: Pool taking: 185.137.221.158 Sep 25 04:17:28 volumio ntpd[1002]: DNS: Pool taking: 31.121.161.188 Sep 25 04:17:28 volumio ntpd[1002]: DNS: Pool taking: 57.129.141.122 Sep 25 04:17:28 volumio ntpd[1002]: DNS: Pool taking: 131.111.8.60 Sep 25 04:17:28 volumio ntpd[1002]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Sep 25 04:17:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1031915. Sep 25 04:17:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 25 04:17:29 volumio go-librespot[32150]: go-librespot daemon starting... Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=info msg="running go-librespot 0.6.2" Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=debug msg="app state loaded" Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=info msg="zeroconf server listening on port 32825" Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=debug msg="obtained new client token: AAFWAec7wxyoqt/f0l+ZWhU1yN99Y0LDu22BLsps4GqqzU/YKf5SEemSBem8rGi58T60Esd0Bln3G2/WAjr7Nm8JEdnohyDnMwzWkNjg7Y6TUJkTWlCSrE0d84Qf91HUvJtCQzuw6mfNL2y2l4kiLvWpVoAPLYOmR+ytfQXuJ2jmksjgs4ptVGwzWqsTnHxI0/LFzCP1hlb8v8jnKOkUOJbNIsHt/qBtvKn7WJ5B/QBUDgjpih8e" Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=debug msg="completed keyexchange" Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=debug msg="completed challenge" Sep 25 04:17:29 volumio volumio[31133]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Sep 25 04:17:29 volumio volumio[31133]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Sep 25 04:17:29 volumio volumio[31133]: info: Streaming services startup Sep 25 04:17:29 volumio volumio[31133]: info: Starting Streaming Daemon Sep 25 04:17:29 volumio sudo[32162]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 25 04:17:29 volumio sudo[32162]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:29 volumio volumio[31133]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=info msg="authenticated AP" username="a3*****************63" Sep 25 04:17:29 volumio sudo[32162]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:29 volumio volumio[31133]: info: Discovery: Restarting Advertising Sep 25 04:17:29 volumio sudo[32170]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 25 04:17:29 volumio sudo[32170]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:29 volumio volumio[31133]: info: Getting Spotify volume Sep 25 04:17:29 volumio sudo[32170]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:29 volumio volumio[31133]: info: Initializing connection to go-librespot Websocket Sep 25 04:17:29 volumio go-librespot[32151]: time="2026-09-25T04:17:29+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 25 04:17:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 25 04:17:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 25 04:17:29 volumio sudo[32188]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Sep 25 04:17:29 volumio sudo[32188]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 25 04:17:29 volumio sudo[32188]: pam_unix(sudo:session): session closed for user root Sep 25 04:17:29 volumio volumio[31133]: error: Cannot start Volumio Streaming Daemon Sep 25 04:17:29 volumio volumio[31133]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Sep 25 04:17:29 volumio volumio[31133]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Sep 25 04:17:29 volumio volumio[31133]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 25 04:17:30 volumio volumio[31133]: Error: socket hang up Sep 25 04:17:30 volumio volumio[31133]: at connResetException (node:internal/errors:720:14) Sep 25 04:17:30 volumio volumio[31133]: at Socket.socketOnEnd (node:_http_client:519:23) Sep 25 04:17:30 volumio volumio[31133]: at Socket.emit (node:events:526:35) Sep 25 04:17:30 volumio volumio[31133]: at endReadableNT (node:internal/streams/readable:1376:12) Sep 25 04:17:30 volumio volumio[31133]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Sep 25 04:17:30 volumio volumio[31133]: code: 'ECONNRESET', Sep 25 04:17:30 volumio volumio[31133]: response: undefined Sep 25 04:17:30 volumio volumio[31133]: } Sep 25 04:17:30 volumio volumio[31133]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 25 04:17:30 volumio sudo[32207]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-09-25 04:16' Sep 25 04:17:30 volumio sudo[32207]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"