Aug 26 21:08:30 volumio5 bluealsa[1036]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_44_34_A2_2A_B4_5B, ...) Aug 26 21:08:31 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:31.859+02:00 level=INFO msg="new address was allocated" component=ble/conn old=1 new=2 Aug 26 21:08:32 volumio5 dbus-daemon[899]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.29" (uid=0 pid=2317 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.2" (uid=0 pid=898 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.340+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s Aug 26 21:08:32 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 21:08:32 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 21:08:32 volumio5 volumio[1298]: info: Discovery: Getting this device information Aug 26 21:08:32 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:32 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:32 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.458+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=http://pushupdates.volumio.org duration=116.400292ms Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.460+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.520590429s timeout=20s Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.460+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" Aug 26 21:08:32 volumio5 volumio[1298]: verbose: New Socket.io Connection to 192.168.76.118:3000 from 192.168.76.104 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 19 Aug 26 21:08:32 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 26 21:08:32 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.512+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.76.104:62096 Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.512+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=172.072036ms Aug 26 21:08:32 volumio5 volumio[1298]: info: Received Get System Info Aug 26 21:08:32 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 21:08:32 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 21:08:32 volumio5 volumio[1298]: info: Discovery: Getting this device information Aug 26 21:08:32 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:32 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:32 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.524+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=https://functions.volumio.cloud duration=181.679015ms Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.524+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=https://functions.volumio.cloud duration=182.222494ms Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.524+02:00 level=INFO msg="emitting device name changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" name=Volumio5 Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.565+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=https://www.googleapis.com duration=223.848881ms Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.593+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=251.254634ms Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.625+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=https://securetoken.googleapis.com duration=283.512357ms Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.633+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=292.667484ms Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.673+02:00 level=INFO msg="emitting device language changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" language=en Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.797+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=455.274579ms Aug 26 21:08:32 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:32.883+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=http://cddb.volumio.org duration=542.118586ms Aug 26 21:08:33 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.001+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" timezone=Europe/Stockholm Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.021+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=http://plugins.volumio.org duration=679.068905ms Aug 26 21:08:33 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 26 21:08:33 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.127+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=https://google.com duration=786.738087ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.139+02:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m47.418268171s timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.288+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=4m36.401606367s timeout=10s endpoint=https://database.volumio.cloud duration=945.341449ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.480+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.70246856s timeout=20s Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.480+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.541+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" available=true connected=true macAddress=88:a2:9e:b4:13:19 ip4Address=192.168.76.118/24 ip6Address= Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.600+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.615+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=14.764263ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.643+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=42.612626ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.646+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=http://pushupdates.volumio.org duration=45.516249ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.646+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=45.766526ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.720+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=https://www.googleapis.com duration=119.628136ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.766+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=https://securetoken.googleapis.com duration=165.398513ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.766+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=165.442606ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.788+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=https://database.volumio.cloud duration=186.778113ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.822+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=https://functions.volumio.cloud duration=221.170702ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.850+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=http://cddb.volumio.org duration=248.813843ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.858+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=https://functions.volumio.cloud duration=256.657455ms Aug 26 21:08:33 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:33.967+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=http://plugins.volumio.org duration=365.485782ms Aug 26 21:08:34 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:34.203+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3m41.525583102s timeout=10s endpoint=https://google.com duration=602.751466ms Aug 26 21:08:34 volumio5 volumio[1298]: info: Received Get System Info Aug 26 21:08:34 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 21:08:34 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 21:08:34 volumio5 volumio[1298]: info: Discovery: Getting this device information Aug 26 21:08:34 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:34 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:34 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 21:08:34 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:34.263+02:00 level=INFO msg="emitting device name changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" name=Volumio5 Aug 26 21:08:34 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:34.381+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.010+02:00 level=INFO msg="emitting device language changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" language=en Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.309+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" setupComplete=true Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.490+02:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="00:00:00:00:00:00%01 @ 0x1400ed0" latency=3.32077846s platform=PLATFORM_IOS version=6.260807.0 Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.523+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.76.104:62096 @ 0x14012c0" latency=55.717552ms timeout=20s Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.523+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" Aug 26 21:08:35 volumio5 volumio[1298]: info: Received Get System Info Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 21:08:35 volumio5 volumio[1298]: info: Discovery: Getting this device information Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:35 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.526+02:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" name=Volumio5 Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.526+02:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" language=en Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.528+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" timezone=Europe/Stockholm Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.528+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" available=true connected=true macAddress=88:a2:9e:b4:13:19 ip4Address=192.168.76.118/24 ip6Address= Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.529+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.529+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" setupComplete=true Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 21:08:35 volumio5 volumio[1298]: amixer -c 0 info | grep "vc4-hdmi-0" Aug 26 21:08:35 volumio5 volumio[1298]: Card sysdefault:0 'vc4hdmi0'/'vc4-hdmi-0' Aug 26 21:08:35 volumio5 volumio[1298]: amixer -c 1 info | grep "vc4-hdmi-1" Aug 26 21:08:35 volumio5 volumio[1298]: Card sysdefault:1 'vc4hdmi1'/'vc4-hdmi-1' Aug 26 21:08:35 volumio5 volumio[1298]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Aug 26 21:08:35 volumio5 volumio[1298]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 26 21:08:35 volumio5 volumio[1298]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\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)"} Aug 26 21:08:35 volumio5 volumio[1298]: amixer -c 5 info | grep "EVO4" Aug 26 21:08:35 volumio5 volumio[1298]: Card sysdefault:5 'EVO4'/'Audient EVO4 at usb-xhci-hcd.0-2, high speed' Aug 26 21:08:35 volumio5 volumio[1298]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Aug 26 21:08:35 volumio5 volumio[1298]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 26 21:08:35 volumio5 volumio[1298]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\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)"} Aug 26 21:08:35 volumio5 volumio[1298]: amixer -c 5 info | grep "EVO4" Aug 26 21:08:35 volumio5 volumio[1298]: Card sysdefault:5 'EVO4'/'Audient EVO4 at usb-xhci-hcd.0-2, high speed' Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.618+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" selectedOutputId=5 Aug 26 21:08:35 volumio5 volumio[1298]: info: Received Get System Info Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 21:08:35 volumio5 volumio[1298]: info: Discovery: Getting this device information Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:35 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.638+02:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" currentVersion=4.119 latestVersion=4.119 Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.638+02:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.76.104:62096 @ 0x14012c0" status=UPDATE_STATUS_NONE progress=0 Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.638+02:00 level=INFO msg="emitting user changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" userId=QeoEngXWQ3ODxae2h7tujNDpYHW2 Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.638+02:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" providers=9 Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.638+02:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" plugins=71 Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:35 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.642+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" state=STATUS_STOPPED positionMs=0 volume=50 Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.642+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.76.104:62096 @ 0x14012c0" id="mnt/NAS/Nas/1001.Albums.You.Must.Hear.Before.You.Die.-.Part.4.Of.4.(FLAC)/0782. Nirvana - MTV UnpluggedIn New York (1994)/1. Nirvana - About a Girl.flac" title="About a Girl" Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.911+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" timezone=Europe/Stockholm Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.917+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" available=true connected=true macAddress=88:a2:9e:b4:13:19 ip4Address=192.168.76.118/24 ip6Address= Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.918+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.918+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" setupComplete=true Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 21:08:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 21:08:35 volumio5 volumio[1298]: amixer -c 0 info | grep "vc4-hdmi-0" Aug 26 21:08:35 volumio5 volumio[1298]: Card sysdefault:0 'vc4hdmi0'/'vc4-hdmi-0' Aug 26 21:08:35 volumio5 volumio[1298]: amixer -c 1 info | grep "vc4-hdmi-1" Aug 26 21:08:35 volumio5 volumio[1298]: Card sysdefault:1 'vc4hdmi1'/'vc4-hdmi-1' Aug 26 21:08:35 volumio5 volumio[1298]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Aug 26 21:08:35 volumio5 volumio[1298]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 26 21:08:35 volumio5 volumio[1298]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\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)"} Aug 26 21:08:35 volumio5 volumio[1298]: amixer -c 5 info | grep "EVO4" Aug 26 21:08:35 volumio5 volumio[1298]: Card sysdefault:5 'EVO4'/'Audient EVO4 at usb-xhci-hcd.0-2, high speed' Aug 26 21:08:35 volumio5 volumio[1298]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Aug 26 21:08:35 volumio5 volumio[1298]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 26 21:08:35 volumio5 volumio[1298]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\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)"} Aug 26 21:08:35 volumio5 volumio[1298]: amixer -c 5 info | grep "EVO4" Aug 26 21:08:35 volumio5 volumio[1298]: Card sysdefault:5 'EVO4'/'Audient EVO4 at usb-xhci-hcd.0-2, high speed' Aug 26 21:08:35 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:35.988+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" selectedOutputId=5 Aug 26 21:08:36 volumio5 volumio[1298]: info: Received Get System Info Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 21:08:36 volumio5 volumio[1298]: info: Discovery: Getting this device information Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:36 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.011+02:00 level=INFO msg="emitting software info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" currentVersion=4.119 latestVersion=4.119 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.011+02:00 level=INFO msg="emitting software update progress event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" status=UPDATE_STATUS_NONE progress=0 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.011+02:00 level=INFO msg="emitting user changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" userId=QeoEngXWQ3ODxae2h7tujNDpYHW2 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.011+02:00 level=INFO msg="emitting music providers changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" providers=9 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.011+02:00 level=INFO msg="emitting plugins changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" plugins=71 Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:36 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.014+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" state=STATUS_STOPPED positionMs=0 volume=50 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.014+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" id="mnt/NAS/Nas/1001.Albums.You.Must.Hear.Before.You.Die.-.Part.4.Of.4.(FLAC)/0782. Nirvana - MTV UnpluggedIn New York (1994)/1. Nirvana - About a Girl.flac" title="About a Girl" Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 21:08:36 volumio5 volumio[1298]: amixer -c 0 info | grep "vc4-hdmi-0" Aug 26 21:08:36 volumio5 volumio[1298]: Card sysdefault:0 'vc4hdmi0'/'vc4-hdmi-0' Aug 26 21:08:36 volumio5 volumio[1298]: amixer -c 1 info | grep "vc4-hdmi-1" Aug 26 21:08:36 volumio5 volumio[1298]: Card sysdefault:1 'vc4hdmi1'/'vc4-hdmi-1' Aug 26 21:08:36 volumio5 volumio[1298]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Aug 26 21:08:36 volumio5 volumio[1298]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 26 21:08:36 volumio5 volumio[1298]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\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)"} Aug 26 21:08:36 volumio5 volumio[1298]: amixer -c 5 info | grep "EVO4" Aug 26 21:08:36 volumio5 volumio[1298]: Card sysdefault:5 'EVO4'/'Audient EVO4 at usb-xhci-hcd.0-2, high speed' Aug 26 21:08:36 volumio5 volumio[1298]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Aug 26 21:08:36 volumio5 volumio[1298]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 26 21:08:36 volumio5 volumio[1298]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\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)"} Aug 26 21:08:36 volumio5 volumio[1298]: amixer -c 5 info | grep "EVO4" Aug 26 21:08:36 volumio5 volumio[1298]: Card sysdefault:5 'EVO4'/'Audient EVO4 at usb-xhci-hcd.0-2, high speed' Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.333+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" selectedOutputId=5 Aug 26 21:08:36 volumio5 volumio[1298]: info: Received Get System Info Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 21:08:36 volumio5 volumio[1298]: info: Discovery: Getting this device information Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:36 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.361+02:00 level=INFO msg="emitting software info changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" currentVersion=4.119 latestVersion=4.119 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.361+02:00 level=INFO msg="emitting software update progress event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" status=UPDATE_STATUS_NONE progress=0 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.361+02:00 level=INFO msg="emitting user changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" userId=QeoEngXWQ3ODxae2h7tujNDpYHW2 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.361+02:00 level=INFO msg="emitting music providers changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" providers=9 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.361+02:00 level=INFO msg="emitting plugins changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" plugins=71 Aug 26 21:08:36 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:36 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.364+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" state=STATUS_STOPPED positionMs=0 volume=50 Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.364+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1400ed0" id="mnt/NAS/Nas/1001.Albums.You.Must.Hear.Before.You.Die.-.Part.4.Of.4.(FLAC)/0782. Nirvana - MTV UnpluggedIn New York (1994)/1. Nirvana - About a Girl.flac" title="About a Girl" Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.754+02: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.76.104:62096 @ 0x1400ed0" latency=55.130533ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.901+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%01,192.168.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.921+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=19.716955ms Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.951+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=49.437203ms Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.952+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=50.154645ms Aug 26 21:08:36 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:36.952+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=http://pushupdates.volumio.org duration=50.522386ms Aug 26 21:08:37 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:37.033+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=https://www.googleapis.com duration=131.827589ms Aug 26 21:08:37 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:37.063+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=162.098464ms Aug 26 21:08:37 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:37.069+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=https://securetoken.googleapis.com duration=167.488027ms Aug 26 21:08:37 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:37.074+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=https://functions.volumio.cloud duration=172.431368ms Aug 26 21:08:37 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:37.074+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=https://functions.volumio.cloud duration=172.93381ms Aug 26 21:08:37 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:37.079+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=https://database.volumio.cloud duration=176.903746ms Aug 26 21:08:37 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:37.169+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=http://cddb.volumio.org duration=267.718706ms Aug 26 21:08:37 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:37.265+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=http://plugins.volumio.org duration=363.097563ms Aug 26 21:08:37 volumio5 volumio5-onboarding[2317]: time=2026-08-26T21:08:37.506+02: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.76.104:62096 @ 0x1400ed0" latency=180.410513ms timeout=10s endpoint=https://google.com duration=605.18292ms Aug 26 21:08:37 volumio5 sudo[2652]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 26 21:08:37 volumio5 sudo[2652]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:08:37 volumio5 sudo[2652]: pam_unix(sudo:session): session closed for user root Aug 26 21:08:37 volumio5 sudo[2654]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 26 21:08:37 volumio5 sudo[2654]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:08:37 volumio5 sudo[2654]: pam_unix(sudo:session): session closed for user root Aug 26 21:08:37 volumio5 volumio[1298]: verbose: New Socket.io Connection to 192.168.76.118 from 192.168.76.104 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 19 Aug 26 21:08:38 volumio5 sudo[2658]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 26 21:08:38 volumio5 sudo[2658]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:08:38 volumio5 sudo[2658]: pam_unix(sudo:session): session closed for user root Aug 26 21:08:38 volumio5 sudo[2660]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 26 21:08:38 volumio5 sudo[2660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:08:38 volumio5 sudo[2660]: pam_unix(sudo:session): session closed for user root Aug 26 21:08:38 volumio5 volumio[1298]: verbose: New Socket.io Connection to 192.168.76.118 from 192.168.76.104 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 19 Aug 26 21:08:38 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:38 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:38 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 26 21:08:38 volumio5 volumio[1298]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 26 21:08:38 volumio5 volumio[1298]: info: Listing playlists Aug 26 21:08:38 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 26 21:08:38 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 26 21:08:38 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 26 21:08:38 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 26 21:08:38 volumio5 volumio[1298]: error: error Aug 26 21:08:40 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 21:08:40 volumio5 volumio[1298]: info: Received Get System Info Aug 26 21:08:40 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 21:08:40 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 21:08:40 volumio5 volumio[1298]: info: Discovery: Getting this device information Aug 26 21:08:40 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:40 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:40 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 21:08:41 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 21:08:41 volumio5 volumio[1298]: info: Received Get System Info Aug 26 21:08:41 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 21:08:41 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 21:08:41 volumio5 volumio[1298]: info: Discovery: Getting this device information Aug 26 21:08:41 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:41 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:41 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 21:08:43 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 21:08:43 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 26 21:08:46 volumio5 volumio[1298]: info: Tunnel connection is inactive, restarting it Aug 26 21:08:46 volumio5 volumio[1298]: info: Starting Tunnel 1 Aug 26 21:08:46 volumio5 volumio[1298]: info: Starting Tunnel Connection Checker Aug 26 21:08:46 volumio5 sudo[2684]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Aug 26 21:08:46 volumio5 sudo[2684]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:08:46 volumio5 systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Aug 26 21:08:47 volumio5 sudo[2684]: pam_unix(sudo:session): session closed for user root Aug 26 21:08:47 volumio5 volumio[1298]: info: Remote SSH Started Aug 26 21:08:47 volumio5 autossh[2687]: port set to 0, monitoring disabled Aug 26 21:08:47 volumio5 autossh[2687]: starting ssh (count 1) Aug 26 21:08:47 volumio5 autossh[2687]: ssh child pid is 2690 Aug 26 21:08:47 volumio5 volumio[1298]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 26 21:08:47 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:47 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:47 volumio5 volumiossh-tunnel[2690]: Warning: Permanently added '[eu9.myvolumio.org]:2222' (RSA) to the list of known hosts. Aug 26 21:08:56 volumio5 volumio[1298]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 26 21:08:56 volumio5 volumio[1298]: info: [RpiEepromUpdater] Channel default version: Tue May 26 15:01:25 UTC 2026 (1779807685) Aug 26 21:08:56 volumio5 volumio[1298]: info: [RpiEepromUpdater] Channel latest version: Tue May 26 15:01:25 UTC 2026 (1779807685) Aug 26 21:08:56 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 26 21:08:56 volumio5 volumio[1298]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 26 21:08:56 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 26 21:08:56 volumio5 volumio[1298]: info: Received Get System Version Aug 26 21:08:56 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 26 21:08:56 volumio5 volumio[1298]: info: Received Get System Info Aug 26 21:08:56 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 21:08:56 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 21:08:56 volumio5 volumio[1298]: info: Discovery: Getting this device information Aug 26 21:08:56 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:08:56 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:08:56 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 21:09:12 volumio5 volumio[1298]: info: CALLMETHOD: system_controller rpi_eeprom_updater refreshPackageDatabase undefined Aug 26 21:09:12 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: rpi_eeprom_updater , refreshPackageDatabase Aug 26 21:09:12 volumio5 volumio[1298]: info: [RpiEepromUpdater] Manual package database refresh triggered Aug 26 21:09:12 volumio5 volumio[1298]: info: [RpiEepromUpdater] Checking for rpi-eeprom package updates Aug 26 21:09:12 volumio5 volumio[1298]: info: [RpiEepromUpdater] Service not active or not found, continuing... Aug 26 21:09:12 volumio5 sudo[2823]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/apt-get update Aug 26 21:09:12 volumio5 sudo[2823]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:09:14 volumio5 sudo[2823]: pam_unix(sudo:session): session closed for user root Aug 26 21:09:15 volumio5 volumio[1298]: info: [RpiEepromUpdater] Package is already up to date: 28.27-1 Aug 26 21:09:15 volumio5 volumio[1298]: info: [RpiEepromUpdater] Starting rpi-eeprom-update service Aug 26 21:09:15 volumio5 sudo[2973]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start rpi-eeprom-update.service Aug 26 21:09:15 volumio5 sudo[2973]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:09:15 volumio5 sudo[2973]: pam_unix(sudo:session): session closed for user root Aug 26 21:09:15 volumio5 volumio[1298]: warn: [RpiEepromUpdater] Could not start service: Command failed: sudo /bin/systemctl start rpi-eeprom-update.service Aug 26 21:09:15 volumio5 volumio[1298]: Failed to start rpi-eeprom-update.service: Unit rpi-eeprom-update.service is masked. Aug 26 21:09:15 volumio5 volumio[1298]: info: [RpiEepromUpdater] Manual refresh: package already current Aug 26 21:09:15 volumio5 volumio[1298]: info: [RpiEepromUpdater] Refreshing UI after package update Aug 26 21:09:15 volumio5 volumio[1298]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 26 21:09:15 volumio5 volumio[1298]: info: [RpiEepromUpdater] Channel default version: Tue May 26 15:01:25 UTC 2026 (1779807685) Aug 26 21:09:15 volumio5 volumio[1298]: info: [RpiEepromUpdater] Channel latest version: Tue May 26 15:01:25 UTC 2026 (1779807685) Aug 26 21:09:27 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 21:09:27 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 26 21:09:33 volumio5 volumio[1298]: info: Enabling plugin spop Aug 26 21:09:33 volumio5 volumio[1298]: info: Loading plugin "spop"... Aug 26 21:09:34 volumio5 volumio[1298]: info: PLUGIN START: spop Aug 26 21:09:34 volumio5 volumio[1298]: info: Creating Spotify config file Aug 26 21:09:34 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 21:09:34 volumio5 volumio[1298]: info: Done. Aug 26 21:09:34 volumio5 volumio[1298]: info: Spotify config file written Aug 26 21:09:34 volumio5 volumio[1298]: info: No need to fix Spotify hosts Aug 26 21:09:34 volumio5 sudo[3079]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 26 21:09:34 volumio5 sudo[3079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:09:34 volumio5 systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 26 21:09:34 volumio5 systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 26 21:09:34 volumio5 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 26 21:09:34 volumio5 go-librespot[3081]: go-librespot daemon starting... Aug 26 21:09:34 volumio5 sudo[3079]: pam_unix(sudo:session): session closed for user root Aug 26 21:09:34 volumio5 volumio[1298]: info: New Spotify access tokenBQC3-Le4O2... Aug 26 21:09:34 volumio5 volumio[1298]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 26 21:09:34 volumio5 go-librespot[3082]: time="2026-08-26T21:09:34+02:00" level=info msg="running go-librespot 0.7.1" Aug 26 21:09:34 volumio5 go-librespot[3082]: time="2026-08-26T21:09:34+02:00" level=debug msg="app state loaded" Aug 26 21:09:34 volumio5 go-librespot[3082]: time="2026-08-26T21:09:34+02:00" level=debug msg="stored credentials not found" Aug 26 21:09:34 volumio5 go-librespot[3082]: time="2026-08-26T21:09:34+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 26 21:09:34 volumio5 volumio[1298]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 26 21:09:35 volumio5 volumio[1298]: SPOTIFY: User informations: {"account_id":"0HH5fMzHw3","country":"SE","display_name":"nisse.p","email":"nisse.p@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/nisse.p"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/nisse.p","id":"nisse.p","images":[],"product":"premium","type":"user","uri":"spotify:user:nisse.p"} Aug 26 21:09:35 volumio5 volumio[1298]: info: Spotify Successfully logged in Aug 26 21:09:35 volumio5 volumio[1298]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 26 21:09:35 volumio5 volumio[1298]: info: [1787771374998] CoreMusicLibrary::Adding element Spotify Aug 26 21:09:35 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 21:09:35 volumio5 volumio[1298]: Cannot find translation for source Spotify Aug 26 21:09:35 volumio5 go-librespot[3082]: time="2026-08-26T21:09:35+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 26 21:09:35 volumio5 go-librespot[3082]: time="2026-08-26T21:09:35+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 26 21:09:35 volumio5 go-librespot[3082]: time="2026-08-26T21:09:35+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 26 21:09:35 volumio5 go-librespot[3082]: time="2026-08-26T21:09:35+02:00" level=info msg="zeroconf server listening on port 45863" Aug 26 21:09:35 volumio5 go-librespot[3082]: time="2026-08-26T21:09:35+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 26 21:09:36 volumio5 volumiossh-tunnel[2690]: Connection to eu9.myvolumio.org closed by remote host. Aug 26 21:09:36 volumio5 autossh[2687]: ssh exited with error status 255; restarting ssh Aug 26 21:09:36 volumio5 autossh[2687]: starting ssh (count 2) Aug 26 21:09:36 volumio5 autossh[2687]: ssh child pid is 3092 Aug 26 21:09:36 volumio5 volumiossh-tunnel[3092]: ssh: connect to host eu9.myvolumio.org port 2222: Connection refused Aug 26 21:09:36 volumio5 autossh[2687]: ssh exited with error status 255; restarting ssh Aug 26 21:09:36 volumio5 autossh[2687]: starting ssh (count 3) Aug 26 21:09:36 volumio5 autossh[2687]: ssh child pid is 3093 Aug 26 21:09:36 volumio5 volumiossh-tunnel[3093]: ssh: connect to host eu9.myvolumio.org port 2222: Connection refused Aug 26 21:09:36 volumio5 autossh[2687]: ssh exited with error status 255; restarting ssh Aug 26 21:09:36 volumio5 autossh[2687]: starting ssh (count 4) Aug 26 21:09:36 volumio5 autossh[2687]: ssh child pid is 3094 Aug 26 21:09:36 volumio5 volumiossh-tunnel[3094]: ssh: connect to host eu9.myvolumio.org port 2222: Connection refused Aug 26 21:09:36 volumio5 autossh[2687]: ssh exited with error status 255; restarting ssh Aug 26 21:09:36 volumio5 autossh[2687]: starting ssh (count 5) Aug 26 21:09:36 volumio5 autossh[2687]: ssh child pid is 3095 Aug 26 21:09:36 volumio5 volumiossh-tunnel[3095]: ssh: connect to host eu9.myvolumio.org port 2222: Connection refused Aug 26 21:09:36 volumio5 autossh[2687]: ssh exited with error status 255; restarting ssh Aug 26 21:09:36 volumio5 autossh[2687]: starting ssh (count 6) Aug 26 21:09:36 volumio5 autossh[2687]: ssh child pid is 3096 Aug 26 21:09:36 volumio5 volumiossh-tunnel[3096]: ssh: connect to host eu9.myvolumio.org port 2222: Connection refused Aug 26 21:09:36 volumio5 autossh[2687]: ssh exited with error status 255; restarting ssh Aug 26 21:09:37 volumio5 volumio[1298]: info: go-librespot daemon successfully initialized Aug 26 21:09:38 volumio5 autossh[2687]: starting ssh (count 7) Aug 26 21:09:38 volumio5 autossh[2687]: ssh child pid is 3107 Aug 26 21:09:38 volumio5 volumiossh-tunnel[3107]: ssh: connect to host eu9.myvolumio.org port 2222: Connection refused Aug 26 21:09:38 volumio5 autossh[2687]: ssh exited with error status 255; restarting ssh Aug 26 21:09:40 volumio5 volumio[1298]: info: Initializing connection to go-librespot Websocket Aug 26 21:09:40 volumio5 go-librespot[3082]: time="2026-08-26T21:09:40+02:00" level=debug msg="new websocket client" Aug 26 21:09:40 volumio5 volumio[1298]: info: Connection to go-librespot Websocket established Aug 26 21:09:42 volumio5 volumio[1298]: info: Received OAUTH Data Aug 26 21:09:42 volumio5 volumio[1298]: info: Executing Spotify Oauth Login Aug 26 21:09:42 volumio5 volumio[1298]: info: Saving Spotify Refresh Token Aug 26 21:09:42 volumio5 volumio[1298]: info: New Spotify access tokenBQAh3A0kBP... Aug 26 21:09:42 volumio5 volumio[1298]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 26 21:09:42 volumio5 sudo[3123]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 26 21:09:42 volumio5 sudo[3123]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:09:42 volumio5 sudo[3123]: pam_unix(sudo:session): session closed for user root Aug 26 21:09:42 volumio5 sudo[3125]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 26 21:09:42 volumio5 sudo[3125]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:09:42 volumio5 sudo[3125]: pam_unix(sudo:session): session closed for user root Aug 26 21:09:42 volumio5 volumio[1298]: verbose: New Socket.io Connection to 192.168.76.118 from 192.168.76.104 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 6 Aug 26 21:09:42 volumio5 volumio[1298]: SPOTIFY: User informations: {"account_id":"0HH5fMzHw3","country":"SE","display_name":"nisse.p","email":"nisse.p@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/nisse.p"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/nisse.p","id":"nisse.p","images":[],"product":"premium","type":"user","uri":"spotify:user:nisse.p"} Aug 26 21:09:42 volumio5 volumio[1298]: info: Creating Spotify config file Aug 26 21:09:42 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 21:09:42 volumio5 volumio[1298]: info: Spotify config file written Aug 26 21:09:42 volumio5 sudo[3129]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 26 21:09:42 volumio5 sudo[3129]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 21:09:42 volumio5 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 26 21:09:42 volumio5 volumio[1298]: info: Connection to go-librespot Websocket closed Aug 26 21:09:42 volumio5 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 26 21:09:42 volumio5 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 26 21:09:42 volumio5 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 26 21:09:42 volumio5 sudo[3129]: pam_unix(sudo:session): session closed for user root Aug 26 21:09:42 volumio5 go-librespot[3131]: go-librespot daemon starting... Aug 26 21:09:42 volumio5 go-librespot[3132]: time="2026-08-26T21:09:42+02:00" level=info msg="running go-librespot 0.7.1" Aug 26 21:09:42 volumio5 go-librespot[3132]: time="2026-08-26T21:09:42+02:00" level=debug msg="app state loaded" Aug 26 21:09:42 volumio5 go-librespot[3132]: time="2026-08-26T21:09:42+02:00" level=debug msg="stored credentials not found" Aug 26 21:09:42 volumio5 go-librespot[3132]: time="2026-08-26T21:09:42+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 26 21:09:42 volumio5 volumio[1298]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 26 21:09:43 volumio5 volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 26 21:09:43 volumio5 volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 26 21:09:43 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 26 21:09:43 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 26 21:09:43 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 26 21:09:43 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 26 21:09:43 volumio5 volumio[1298]: info: New Spotify access tokenBQBzKjAJBz... Aug 26 21:09:43 volumio5 volumio[1298]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=info msg="zeroconf server listening on port 40559" Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 26 21:09:43 volumio5 volumio[1298]: SPOTIFY: User informations: {"account_id":"0HH5fMzHw3","country":"SE","display_name":"nisse.p","email":"nisse.p@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/nisse.p"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/nisse.p","id":"nisse.p","images":[],"product":"premium","type":"user","uri":"spotify:user:nisse.p"} Aug 26 21:09:43 volumio5 volumio[1298]: info: Spotify Successfully logged in Aug 26 21:09:43 volumio5 volumio[1298]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 26 21:09:43 volumio5 volumio[1298]: info: [1787771383215] CoreMusicLibrary::Adding element Spotify Aug 26 21:09:43 volumio5 volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 21:09:43 volumio5 volumio[1298]: Cannot find translation for source Spotify Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=debug msg="obtained new client token: AAHcl4kzy+SQUHkJvSP52tQSF8lyGksnezObFpMyb/Y+S6fWiVAvshmpi2lo/sp7jSqsvxRBAcsW145CTvRKXDOhYNtr9O5Ag3I2yGENSwh3rxThwzw56Tj/hI0dGIN4RbCN2RfuWMDN6hZ1ZEqQDDu4oNmqG5T1sqL7E0Z4ZD1P59TLsoG5pB6+bEZjzDZD53B1mQdAbDUQjvWuYhOqfd24dzmBdGrfmwGtJzZujvkXKuux9aBDBk3m" Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=debug msg="completed keyexchange" Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=debug msg="completed challenge" Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=info msg="authenticated AP" username="ni***.p" Aug 26 21:09:43 volumio5 go-librespot[3132]: time="2026-08-26T21:09:43+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 26 21:09:43 volumio5 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 26 21:09:43 volumio5 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 26 21:09:43 volumio5 volumio[1298]: info: Getting Spotify volume Aug 26 21:09:43 volumio5 volumio[1298]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 26 21:09:43 volumio5 volumio[1298]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 26 21:09:43 volumio5 volumio[1298]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 26 21:09:43 volumio5 volumio[1298]: errno: -111, Aug 26 21:09:43 volumio5 volumio[1298]: code: 'ECONNREFUSED', Aug 26 21:09:43 volumio5 volumio[1298]: syscall: 'connect', Aug 26 21:09:43 volumio5 volumio[1298]: address: '127.0.0.1', Aug 26 21:09:43 volumio5 volumio[1298]: port: 9879, Aug 26 21:09:43 volumio5 volumio[1298]: response: undefined Aug 26 21:09:43 volumio5 volumio[1298]: } Aug 26 21:09:43 volumio5 volumio[1298]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 26 21:09:44 volumio5 sudo[3155]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-26 21:08' Aug 26 21:09:44 volumio5 sudo[3155]: 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"