May 27 13:41:16 volumio go-librespot[1705]: time="2026-05-27T13:41:16+02:00" level=trace msg="sent dealer ping" May 27 13:41:16 volumio go-librespot[1705]: time="2026-05-27T13:41:16+02:00" level=trace msg="received dealer pong" May 27 13:41:16 volumio volumio[1172]: info: CorePlayQueue::getTrack 38 May 27 13:41:16 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:16 volumio volumio[1172]: info: Prefetching next song May 27 13:41:16 volumio volumio[1172]: info: [1779882076639] ControllerSpotify::prefetch May 27 13:41:16 volumio volumio[1172]: info: Sending Spotify command with payload to local API: /player/add_to_queue May 27 13:41:16 volumio go-librespot[1705]: time="2026-05-27T13:41:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 13:41:16 volumio go-librespot[1705]: time="2026-05-27T13:41:16+02:00" level=trace msg="prefetch as soon as possible" May 27 13:41:16 volumio go-librespot[1705]: time="2026-05-27T13:41:16+02:00" level=debug msg="prefetching next track" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:16 volumio go-librespot[1705]: time="2026-05-27T13:41:16+02:00" level=debug msg="selected format OGG_VORBIS_320 (484430b56eadc60da5e92c4af490f6c2cc4b5ba9)" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:16 volumio go-librespot[1705]: time="2026-05-27T13:41:16+02:00" level=debug msg="requested aes key for file 484430b56eadc60da5e92c4af490f6c2cc4b5ba9, gid: 1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:17 volumio go-librespot[1705]: time="2026-05-27T13:41:17+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:17 volumio go-librespot[1705]: time="2026-05-27T13:41:17+02:00" level=debug msg="fetched first chunk of 23, total size is 11972416 bytes" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:17 volumio go-librespot[1705]: time="2026-05-27T13:41:17+02:00" level=info msg="prefetched track \"Liberty\" (duration: 344640ms)" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:17 volumio go-librespot[1705]: time="2026-05-27T13:41:17+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:17 volumio go-librespot[1705]: time="2026-05-27T13:41:17+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:17 volumio go-librespot[1705]: time="2026-05-27T13:41:17+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:20 volumio go-librespot[1705]: time="2026-05-27T13:41:20+02:00" level=trace msg="emitting websocket event: not_playing" May 27 13:41:20 volumio go-librespot[1705]: time="2026-05-27T13:41:20+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:20 volumio volumio[1172]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:26kCuRByHY2UgJaciU3Rq7","uri":"spotify:track:0Rv9FyjMoJCnp6ouzro43h","play_origin":"go-librespot"}} May 27 13:41:20 volumio volumio[1172]: error: Failed to decode event: not_playing May 27 13:41:20 volumio go-librespot[1705]: time="2026-05-27T13:41:20+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 13:41:20 volumio go-librespot[1705]: time="2026-05-27T13:41:20+02:00" level=trace msg="emitting websocket event: will_play" May 27 13:41:20 volumio go-librespot[1705]: time="2026-05-27T13:41:20+02:00" level=info msg="loaded track \"Liberty\" (paused: false, position: 0ms, duration: 344640ms, prefetched: true)" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:20 volumio volumio[1172]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:26kCuRByHY2UgJaciU3Rq7","uri":"spotify:track:1ILzp5O3eCNWXDtMozdoGh","play_origin":"go-librespot"}} May 27 13:41:20 volumio go-librespot[1705]: time="2026-05-27T13:41:20+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 13:41:21 volumio go-librespot[1705]: time="2026-05-27T13:41:21+02:00" level=trace msg="scheduling prefetch in 315s" May 27 13:41:21 volumio go-librespot[1705]: time="2026-05-27T13:41:21+02:00" level=trace msg="emitting websocket event: metadata" May 27 13:41:21 volumio volumio[1172]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1ILzp5O3eCNWXDtMozdoGh","name":"Liberty","artist_names":["Anette Askvik"],"album_name":"Liberty (original edition)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e021e393c08ddd4c0854c758400","position":0,"duration":344640,"release_date":"year:2011 month:3 day:7","track_number":1,"disc_number":1}} May 27 13:41:21 volumio go-librespot[1705]: time="2026-05-27T13:41:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 13:41:21 volumio go-librespot[1705]: time="2026-05-27T13:41:21+02:00" level=trace msg="emitting websocket event: playing" May 27 13:41:21 volumio volumio[1172]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:26kCuRByHY2UgJaciU3Rq7","uri":"spotify:track:1ILzp5O3eCNWXDtMozdoGh","resume":false,"play_origin":"go-librespot"}} May 27 13:41:21 volumio volumio[1172]: SPOTIFY: PUSH STATE SPOTIFY May 27 13:41:21 volumio volumio[1172]: SPOTIFY: {"status":"play","service":"spop","title":"Liberty","artist":"Anette Askvik","album":"Liberty (original edition)","albumart":"https://i.scdn.co/image/ab67616d00001e021e393c08ddd4c0854c758400","uri":"spotify:track:1ILzp5O3eCNWXDtMozdoGh","trackType":"spotify","seek":0,"duration":344,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::servicePushState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 38 May 27 13:41:21 volumio volumio[1172]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Liberty","artist":"Anette Askvik","album":"Liberty (original edition)","albumart":"https://i.scdn.co/image/ab67616d00001e021e393c08ddd4c0854c758400","uri":"spotify:track:1ILzp5O3eCNWXDtMozdoGh","trackType":"spotify","seek":0,"duration":344,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 13:41:21 volumio volumio[1172]: verbose: CURRENT POSITION 38 May 27 13:41:21 volumio volumio[1172]: info: CoreStateMachine::syncState stateService play May 27 13:41:21 volumio volumio[1172]: info: CoreStateMachine::syncState currentStatus play May 27 13:41:21 volumio volumio[1172]: info: Received an update from plugin. extracting info from payload May 27 13:41:21 volumio volumio[1172]: info: CoreStateMachine::pushState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 38 May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::volumioPushState May 27 13:41:21 volumio volumio[1172]: info: MRS: Pushing multiroomSync output update for this device May 27 13:41:21 volumio volumio[1172]: info: MRS: Pushing multiroomSync output May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 38 May 27 13:41:21 volumio volumio[1172]: info: CoreStateMachine::pushState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 38 May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::volumioPushState May 27 13:41:21 volumio volumio[1172]: info: MRS: Pushing multiroomSync output update for this device May 27 13:41:21 volumio volumio[1172]: info: MRS: Pushing multiroomSync output May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 38 May 27 13:41:21 volumio volumio[1172]: info: CoreStateMachine::startPlaybackTimer May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:21 volumio volumio[1172]: SPOTIFY: PUSH STATE SPOTIFY May 27 13:41:21 volumio volumio[1172]: SPOTIFY: {"status":"play","service":"spop","title":"Liberty","artist":"Anette Askvik","album":"Liberty (original edition)","albumart":"https://i.scdn.co/image/ab67616d00001e021e393c08ddd4c0854c758400","uri":"spotify:track:1ILzp5O3eCNWXDtMozdoGh","trackType":"spotify","seek":0,"duration":344,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::servicePushState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:21 volumio volumio[1172]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Liberty","artist":"Anette Askvik","album":"Liberty (original edition)","albumart":"https://i.scdn.co/image/ab67616d00001e021e393c08ddd4c0854c758400","uri":"spotify:track:1ILzp5O3eCNWXDtMozdoGh","trackType":"spotify","seek":0,"duration":344,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 13:41:21 volumio volumio[1172]: verbose: CURRENT POSITION 39 May 27 13:41:21 volumio volumio[1172]: info: CoreStateMachine::syncState stateService play May 27 13:41:21 volumio volumio[1172]: info: CoreStateMachine::syncState currentStatus play May 27 13:41:21 volumio volumio[1172]: info: Received an update from plugin. extracting info from payload May 27 13:41:21 volumio volumio[1172]: info: CoreStateMachine::pushState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::volumioPushState May 27 13:41:21 volumio volumio[1172]: info: MRS: Pushing multiroomSync output update for this device May 27 13:41:21 volumio volumio[1172]: info: MRS: Pushing multiroomSync output May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:21 volumio volumio[1172]: info: CoreStateMachine::pushState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::volumioPushState May 27 13:41:21 volumio volumio[1172]: info: MRS: Pushing multiroomSync output update for this device May 27 13:41:21 volumio volumio[1172]: info: MRS: Pushing multiroomSync output May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:21 volumio volumio[1172]: info: CoreStateMachine::pushState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::volumioPushState May 27 13:41:21 volumio volumio[1172]: info: MRS: Pushing multiroomSync output update for this device May 27 13:41:21 volumio volumio[1172]: info: MRS: Pushing multiroomSync output May 27 13:41:21 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:21 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:23 volumio volumio[1172]: info: Executing endpoint metavolumio May 27 13:41:23 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 27 13:41:23 volumio volumio[1172]: info: Executing endpoint metavolumio May 27 13:41:23 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 27 13:41:23 volumio volumio[1172]: info: Executing endpoint metavolumio May 27 13:41:23 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.619+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.201:62304 May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.662+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.1.201:62304 @ 0x349e6c0" latency=54.876316ms timeout=10s May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.662+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.662+02:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.1.201:62304 @ 0x349e6c0" latency=55.881705ms platform=PLATFORM_IOS version=5.260413.0 May 27 13:41:25 volumio volumio[1172]: info: Received Get System Info May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 27 13:41:25 volumio volumio[1172]: info: Discovery: Getting this device information May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:25 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.664+02:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" name=Volumio May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.666+02:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" language=sv May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.668+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" timezone=Europe/Stockholm May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.669+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" available=true connected=false macAddress= ip4Address= ip6Address= May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.673+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" available=true connected=true macAddress=e4:5f:01:d8:09:ed ip4Address=192.168.1.75/24 ip6Address= ssid=NYBYGG_2021 May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.673+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" setupComplete=true May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 13:41:25 volumio volumio[1172]: amixer -c 0 info | grep "bcm2835 ALSA" May 27 13:41:25 volumio volumio[1172]: amixer -c 1 info | grep "bcm2835 Headphones" May 27 13:41:25 volumio volumio[1172]: Card sysdefault:1 'Headphones'/'bcm2835 Headphones' May 27 13:41:25 volumio volumio[1172]: amixer -c 2 info | grep "vc4-hdmi-0" May 27 13:41:25 volumio volumio[1172]: Card sysdefault:2 'vc4hdmi0'/'vc4-hdmi-0' May 27 13:41:25 volumio volumio[1172]: amixer -c 3 info | grep "vc4-hdmi-1" May 27 13:41:25 volumio volumio[1172]: Card sysdefault:3 'vc4hdmi1'/'vc4-hdmi-1' May 27 13:41:25 volumio volumio[1172]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 May 27 13:41:25 volumio volumio[1172]: /bin/sh: 1: /usr/local/bin/alsacap: not found May 27 13:41:25 volumio volumio[1172]: {"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)"} May 27 13:41:25 volumio volumio[1172]: amixer -c 5 info | grep "SMSL USB AUDIO" May 27 13:41:25 volumio volumio[1172]: Card sysdefault:5 'AUDIO'/'SMSL SMSL USB AUDIO at usb-0000:01:00.0-1.1, high speed' May 27 13:41:25 volumio volumio[1172]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 May 27 13:41:25 volumio volumio[1172]: /bin/sh: 1: /usr/local/bin/alsacap: not found May 27 13:41:25 volumio volumio[1172]: {"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)"} May 27 13:41:25 volumio volumio[1172]: amixer -c 5 info | grep "SMSL USB AUDIO" May 27 13:41:25 volumio volumio[1172]: Card sysdefault:5 'AUDIO'/'SMSL SMSL USB AUDIO at usb-0000:01:00.0-1.1, high speed' May 27 13:41:25 volumio volumio[1172]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 7 May 27 13:41:25 volumio volumio[1172]: /bin/sh: 1: /usr/local/bin/alsacap: not found May 27 13:41:25 volumio volumio[1172]: {"cmd":"/usr/local/bin/alsacap -C 7","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 7\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)"} May 27 13:41:25 volumio volumio[1172]: amixer -c 7 info | grep "Loopback" May 27 13:41:25 volumio volumio[1172]: Card sysdefault:7 'Loopback'/'Loopback 1' May 27 13:41:25 volumio volumio[1172]: Mixer name : 'Loopback Mixer' May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.926+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" selectedOutputId=5 May 27 13:41:25 volumio volumio[1172]: info: Received Get System Info May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 27 13:41:25 volumio volumio[1172]: info: Discovery: Getting this device information May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:25 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.940+02:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" currentVersion=4.119 latestVersion=4.119 May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.941+02:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" status=UPDATE_STATUS_NONE progress=0 May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.942+02:00 level=INFO msg="emitting user changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" userId= May 27 13:41:25 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:25.942+02:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" providers=3 May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 27 13:41:25 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 27 13:41:26 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 27 13:41:26 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 27 13:41:26 volumio volumio[1172]: info: Discovery: Getting this device information May 27 13:41:26 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:26 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:26 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 27 13:41:26 volumio volumio[1172]: verbose: New Socket.io Connection to 192.168.1.75:3000 from 192.168.1.201 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 May 27 13:41:26 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 27 13:41:26 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 27 13:41:26 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:26.668+02:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" plugins=65 May 27 13:41:26 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:26 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:26 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:26.672+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" state=STATUS_PLAYING positionMs=5011 volume=100 May 27 13:41:26 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:26.672+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.201:62304 @ 0x349e6c0" id=spotify:track:1ILzp5O3eCNWXDtMozdoGh title=Liberty May 27 13:41:27 volumio bluealsa[972]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_43_A4_7B_DB_72_66, ...) May 27 13:41:28 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:28.765+02:00 level=INFO msg="new address was allocated" component=ble/conn old=1 new=2 May 27 13:41:28 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:29 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:30 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:30.640+02:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.1.201:62304 @ 0x349e6c0" latency=54.085931ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE May 27 13:41:31 volumio sudo[8538]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 27 13:41:31 volumio sudo[8538]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 13:41:31 volumio sudo[8538]: pam_unix(sudo:session): session closed for user root May 27 13:41:31 volumio sudo[8540]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 27 13:41:31 volumio sudo[8540]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 13:41:31 volumio sudo[8540]: pam_unix(sudo:session): session closed for user root May 27 13:41:31 volumio volumio[1172]: verbose: New Socket.io Connection to 192.168.1.75 from 192.168.1.201 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: 12 May 27 13:41:31 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 27 13:41:31 volumio sudo[8544]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 27 13:41:31 volumio sudo[8544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 13:41:31 volumio sudo[8546]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 27 13:41:31 volumio sudo[8546]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 13:41:31 volumio sudo[8544]: pam_unix(sudo:session): session closed for user root May 27 13:41:31 volumio sudo[8546]: pam_unix(sudo:session): session closed for user root May 27 13:41:31 volumio volumio[1172]: verbose: New Socket.io Connection to 192.168.1.75 from 192.168.1.201 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: 12 May 27 13:41:31 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::volumioGetVisibleSources May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:32 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 27 13:41:32 volumio volumio[1172]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom May 27 13:41:32 volumio volumio[1172]: info: Received Get System Info May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 27 13:41:32 volumio volumio[1172]: info: Discovery: Getting this device information May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:32 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:32 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:32 volumio volumio[1172]: info: Listing playlists May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::getUIConfigOnPlugin May 27 13:41:32 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 27 13:41:33 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 27 13:41:33 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 27 13:41:33 volumio volumio[1172]: info: Received Get System Info May 27 13:41:33 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 27 13:41:33 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 27 13:41:33 volumio volumio[1172]: info: Discovery: Getting this device information May 27 13:41:33 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:33 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:33 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 27 13:41:35 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 27 13:41:35 volumio volumio[1172]: info: Received Get System Info May 27 13:41:35 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 27 13:41:35 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 27 13:41:35 volumio volumio[1172]: info: Discovery: Getting this device information May 27 13:41:35 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:35 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:35 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 27 13:41:35 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 27 13:41:35 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 27 13:41:35 volumio volumio[1172]: info: CoreCommandRouter::getUIConfigOnPlugin May 27 13:41:35 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:35.935+02:00 level=INFO msg="new address was allocated" component=ble/conn old=2 new=3 May 27 13:41:36 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:36 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:38 volumio go-librespot[1705]: time="2026-05-27T13:41:38+02:00" level=debug msg="fetched chunk 4/22, size: 524288" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:41 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:41.725+02:00 level=INFO msg="new address was allocated" component=ble/conn old=3 new=4 May 27 13:41:41 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:41 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 27 13:41:42 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:45 volumio go-librespot[1705]: time="2026-05-27T13:41:45+02:00" level=trace msg="received accesspoint ping" May 27 13:41:45 volumio go-librespot[1705]: time="2026-05-27T13:41:45+02:00" level=trace msg="received accesspoint pong ack" May 27 13:41:46 volumio go-librespot[1705]: time="2026-05-27T13:41:46+02:00" level=trace msg="sent dealer ping" May 27 13:41:46 volumio go-librespot[1705]: time="2026-05-27T13:41:46+02:00" level=trace msg="received dealer pong" May 27 13:41:48 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:48.895+02:00 level=INFO msg="new address was allocated" component=ble/conn old=4 new=5 May 27 13:41:49 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:49 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:50 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 27 13:41:50 volumio volumio[1172]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 27 13:41:50 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 27 13:41:50 volumio volumio[1172]: info: Received Get System Version May 27 13:41:50 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 27 13:41:50 volumio volumio[1172]: info: Received Get System Info May 27 13:41:50 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 27 13:41:50 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 27 13:41:50 volumio volumio[1172]: info: Discovery: Getting this device information May 27 13:41:50 volumio volumio[1172]: info: CoreCommandRouter::volumioGetState May 27 13:41:50 volumio volumio[1172]: info: CorePlayQueue::getTrack 39 May 27 13:41:50 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 27 13:41:53 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:53.785+02:00 level=INFO msg="new address was allocated" component=ble/conn old=5 new=6 May 27 13:41:54 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:54 volumio go-librespot[1705]: time="2026-05-27T13:41:54+02:00" level=debug msg="fetched chunk 5/22, size: 524288" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:41:54 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:55 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:55.525+02:00 level=INFO msg="new address was allocated" component=ble/conn old=6 new=7 May 27 13:41:55 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:56 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:56 volumio volumio[1172]: info: CoreCommandRouter::getUIConfigOnPlugin May 27 13:41:58 volumio volumio5-onboarding[1549]: time=2026-05-27T13:41:58.765+02:00 level=INFO msg="new address was allocated" component=ble/conn old=7 new=8 May 27 13:41:58 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:41:59 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:00 volumio volumio[1172]: info: CALLMETHOD: user_interface Systeminfo getsysteminfo undefined May 27 13:42:00 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: Systeminfo , getsysteminfo May 27 13:42:00 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 27 13:42:00 volumio dbus-daemon[747]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.106' (uid=1000 pid=8632 comm="hostnamectl --json short") May 27 13:42:00 volumio systemd[1]: Starting systemd-hostnamed.service - Hostname Service... May 27 13:42:00 volumio dbus-daemon[747]: [system] Successfully activated service 'org.freedesktop.hostname1' May 27 13:42:00 volumio systemd[1]: Started systemd-hostnamed.service - Hostname Service. May 27 13:42:00 volumio dbus-daemon[747]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.107' (uid=0 pid=8634 comm="/lib/systemd/systemd-hostnamed") May 27 13:42:00 volumio systemd[1]: Starting polkit.service - Authorization Manager... May 27 13:42:00 volumio polkitd[8635]: Started polkitd version 122 May 27 13:42:00 volumio polkitd[8635]: Loading rules from directory /etc/polkit-1/rules.d May 27 13:42:00 volumio polkitd[8635]: Loading rules from directory /usr/share/polkit-1/rules.d May 27 13:42:00 volumio polkitd[8635]: Finished loading, compiling and executing 2 rules May 27 13:42:00 volumio dbus-daemon[747]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' May 27 13:42:00 volumio systemd[1]: Started polkit.service - Authorization Manager. May 27 13:42:00 volumio polkitd[8635]: Acquired the name org.freedesktop.PolicyKit1 on the system bus May 27 13:42:00 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.107" (uid=0 pid=8634 comm="/lib/systemd/systemd-hostnamed") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.InteractiveAuthorizationRequired" requested_reply="0" destination=":1.106" (uid=1000 pid=8632 comm="hostnamectl --json short") May 27 13:42:01 volumio volumio5-onboarding[1549]: time=2026-05-27T13:42:01.886+02:00 level=INFO msg="new address was allocated" component=ble/conn old=8 new=9 May 27 13:42:02 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:02 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:02 volumio sudo[8846]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/vcgencmd bootloader_version May 27 13:42:02 volumio sudo[8846]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 13:42:02 volumio sudo[8846]: pam_unix(sudo:session): session closed for user root May 27 13:42:03 volumio volumio[1172]: info: Firmware detection stderr: [sudo] password for volumio: May 27 13:42:03 volumio volumio5-onboarding[1549]: time=2026-05-27T13:42:03.686+02:00 level=INFO msg="new address was allocated" component=ble/conn old=9 new=10 May 27 13:42:03 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:04 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:05 volumio volumio[1172]: error: Audio hardware detection failed, check if "hw_params" exists and is executable: May 27 13:42:05 volumio volumio[1172]: info: CALLMETHOD: user_interface Systeminfo getsysteminfo undefined May 27 13:42:05 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: Systeminfo , getsysteminfo May 27 13:42:05 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 27 13:42:05 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.107" (uid=0 pid=8634 comm="/lib/systemd/systemd-hostnamed") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.InteractiveAuthorizationRequired" requested_reply="0" destination=":1.109" (uid=1000 pid=9391 comm="hostnamectl --json short") May 27 13:42:07 volumio sudo[9576]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/vcgencmd bootloader_version May 27 13:42:07 volumio sudo[9576]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 13:42:07 volumio sudo[9576]: pam_unix(sudo:session): session closed for user root May 27 13:42:08 volumio volumio5-onboarding[1549]: time=2026-05-27T13:42:08.126+02:00 level=INFO msg="new address was allocated" component=ble/conn old=10 new=11 May 27 13:42:08 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:08 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:08 volumio sudo[9664]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 May 27 13:42:08 volumio sudo[9664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 13:42:08 volumio sudo[9664]: pam_unix(sudo:session): session closed for user root May 27 13:42:09 volumio volumio5-onboarding[1549]: time=2026-05-27T13:42:09.955+02:00 level=INFO msg="new address was allocated" component=ble/conn old=11 new=12 May 27 13:42:10 volumio volumio[1172]: error: Audio hardware detection failed, check if "hw_params" exists and is executable: May 27 13:42:10 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:10 volumio go-librespot[1705]: time="2026-05-27T13:42:10+02:00" level=debug msg="fetched chunk 6/22, size: 524288" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:42:10 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:10 volumio kernel: Bluetooth: hci0: Opcode 0x200a failed: -16 May 27 13:42:10 volumio sudo[10105]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 May 27 13:42:10 volumio sudo[10105]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 13:42:10 volumio sudo[10105]: pam_unix(sudo:session): session closed for user root May 27 13:42:11 volumio volumio5-onboarding[1549]: time=2026-05-27T13:42:11.726+02:00 level=INFO msg="new address was allocated" component=ble/conn old=12 new=13 May 27 13:42:11 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:12 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:14 volumio volumio5-onboarding[1549]: time=2026-05-27T13:42:14.875+02:00 level=INFO msg="new address was allocated" component=ble/conn old=13 new=14 May 27 13:42:15 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:15 volumio dbus-daemon[747]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.19" (uid=0 pid=1549 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=834 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 27 13:42:16 volumio go-librespot[1705]: time="2026-05-27T13:42:16+02:00" level=trace msg="sent dealer ping" May 27 13:42:16 volumio go-librespot[1705]: time="2026-05-27T13:42:16+02:00" level=trace msg="received dealer pong" May 27 13:42:26 volumio go-librespot[1705]: time="2026-05-27T13:42:26+02:00" level=debug msg="fetched chunk 7/22, size: 524288" uri="spotify:track:1ILzp5O3eCNWXDtMozdoGh" May 27 13:42:27 volumio volumio[1172]: info: CoreCommandRouter::Close All Modals sent May 27 13:42:28 volumio volumio[1172]: info: CALLMETHOD: user_interface Systeminfo runBench undefined May 27 13:42:28 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: Systeminfo , runBench May 27 13:42:33 volumio volumio[1172]: info: CALLMETHOD: user_interface Systeminfo runSysbench undefined May 27 13:42:33 volumio volumio[1172]: info: CoreCommandRouter::executeOnPlugin: Systeminfo , runSysbench May 27 13:42:33 volumio volumio[1172]: info: Starting full sysbench sequence... May 27 13:42:33 volumio volumio[1172]: error: Sysbench failed: Command failed: sysbench cpu --threads=$(nproc) --time=10 run May 27 13:42:33 volumio volumio[1172]: /bin/sh: 1: sysbench: not found May 27 13:42:33 volumio volumio[1172]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 27 13:42:33 volumio volumio[1172]: Error: Command failed: sysbench cpu --threads=$(nproc) --time=10 run May 27 13:42:33 volumio volumio[1172]: /bin/sh: 1: sysbench: not found May 27 13:42:33 volumio volumio[1172]: at ChildProcess.exithandler (node:child_process:421:12) May 27 13:42:33 volumio volumio[1172]: at ChildProcess.emit (node:events:514:28) May 27 13:42:33 volumio volumio[1172]: at maybeClose (node:internal/child_process:1105:16) May 27 13:42:33 volumio volumio[1172]: at ChildProcess._handle.onexit (node:internal/child_process:305:5) { May 27 13:42:33 volumio volumio[1172]: code: 127, May 27 13:42:33 volumio volumio[1172]: killed: false, May 27 13:42:33 volumio volumio[1172]: signal: null, May 27 13:42:33 volumio volumio[1172]: cmd: 'sysbench cpu --threads=$(nproc) --time=10 run' May 27 13:42:33 volumio volumio[1172]: } May 27 13:42:33 volumio volumio[1172]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 27 13:42:33 volumio sudo[10174]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-27 13:41' May 27 13:42:33 volumio sudo[10174]: 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"