Oct 11 11:13:47 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 6 Oct 11 11:13:47 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:47 volumiojca volumio[1263]: info: Prefetching next song Oct 11 11:13:47 volumiojca volumio[1263]: info: DOING PREFETCH IN MPD Oct 11 11:13:47 volumiojca volumio[1263]: verbose: ControllerMpd::sendMpdCommand add "USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/Lalande - Les Folies de Cardenio C COIN/25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous.flac" Oct 11 11:13:47 volumiojca volumio[1263]: info: Oct 11 11:13:47 volumiojca volumio[1263]: ---------------------------- MPD announces system playlist update Oct 11 11:13:47 volumiojca volumio[1263]: info: Ignoring MPD Status Update Oct 11 11:13:47 volumiojca volumio[1263]: info: sendMpdCommand add "USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/Lalande - Les Folies de Cardenio C COIN/25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous.flac" took 1 milliseconds Oct 11 11:13:47 volumiojca volumio[1263]: verbose: ControllerMpd::sendMpdCommand consume 1 Oct 11 11:13:47 volumiojca volumio[1263]: info: Oct 11 11:13:47 volumiojca volumio[1263]: ---------------------------- MPD announces system playlist update Oct 11 11:13:47 volumiojca volumio[1263]: info: Ignoring MPD Status Update Oct 11 11:13:47 volumiojca volumio[1263]: info: Oct 11 11:13:47 volumiojca volumio[1263]: ---------------------------- MPD announces system playlist update Oct 11 11:13:47 volumiojca volumio[1263]: info: Ignoring MPD Status Update Oct 11 11:13:47 volumiojca volumio[1263]: info: ------------------------------ 3ms Oct 11 11:13:47 volumiojca volumio[1263]: info: sendMpdCommand consume 1 took 2 milliseconds Oct 11 11:13:47 volumiojca volumio[1263]: info: ------------------------------ 2ms Oct 11 11:13:47 volumiojca volumio[1263]: info: ------------------------------ 2ms Oct 11 11:13:52 volumiojca volumio[1263]: info: CoreStateMachine::startPlaybackTimer Oct 11 11:13:52 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:52 volumiojca volumio[1263]: info: CoreStateMachine::pushState Oct 11 11:13:52 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:52 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 11:13:52 volumiojca volumio[1263]: info: CoreCommandRouter::volumioPushState Oct 11 11:13:53 volumiojca volumio[1263]: info: Oct 11 11:13:53 volumiojca volumio[1263]: ---------------------------- MPD announces system playlist update Oct 11 11:13:53 volumiojca volumio[1263]: info: Ignoring MPD Status Update Oct 11 11:13:53 volumiojca volumio[1263]: info: Oct 11 11:13:53 volumiojca volumio[1263]: ---------------------------- MPD announces state update: player Oct 11 11:13:53 volumiojca volumio[1263]: info: ControllerMpd::getState Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::sendMpdCommand status Oct 11 11:13:53 volumiojca volumio[1263]: info: Oct 11 11:13:53 volumiojca volumio[1263]: ---------------------------- MPD announces system playlist update Oct 11 11:13:53 volumiojca volumio[1263]: info: Ignoring MPD Status Update Oct 11 11:13:53 volumiojca volumio[1263]: info: Oct 11 11:13:53 volumiojca volumio[1263]: ---------------------------- MPD announces state update: player Oct 11 11:13:53 volumiojca volumio[1263]: info: ControllerMpd::getState Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::sendMpdCommand status Oct 11 11:13:53 volumiojca volumio[1263]: info: Oct 11 11:13:53 volumiojca volumio[1263]: ---------------------------- MPD announces system playlist update Oct 11 11:13:53 volumiojca volumio[1263]: info: Ignoring MPD Status Update Oct 11 11:13:53 volumiojca volumio[1263]: info: Oct 11 11:13:53 volumiojca volumio[1263]: ---------------------------- MPD announces state update: player Oct 11 11:13:53 volumiojca volumio[1263]: info: ControllerMpd::getState Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::sendMpdCommand status Oct 11 11:13:53 volumiojca volumio[1263]: info: ------------------------------ 3ms Oct 11 11:13:53 volumiojca volumio[1263]: info: sendMpdCommand status took 3 milliseconds Oct 11 11:13:53 volumiojca volumio[1263]: info: ------------------------------ 3ms Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::parseState Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 11:13:53 volumiojca volumio[1263]: info: sendMpdCommand status took 3 milliseconds Oct 11 11:13:53 volumiojca volumio[1263]: info: ------------------------------ 3ms Oct 11 11:13:53 volumiojca volumio[1263]: info: sendMpdCommand status took 2 milliseconds Oct 11 11:13:53 volumiojca volumio[1263]: info: sendMpdCommand playlistinfo took 1 milliseconds Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::parseState Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::parseState Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::parseTrackInfo Oct 11 11:13:53 volumiojca volumio[1263]: info: ControllerMpd::pushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreCommandRouter::servicePushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:53 volumiojca volumio[1263]: verbose: STATE SERVICE {"status":"play","position":0,"seek":7,"duration":78,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2545 Kbps","isStreaming":false,"title":"25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous","artist":"C COIN","album":"Les Folies de Cardenio","uri":"USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/Lalande - Les Folies de Cardenio C COIN/25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous.flac","trackType":"flac"} Oct 11 11:13:53 volumiojca volumio[1263]: verbose: CURRENT POSITION 7 Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::syncState stateService play Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:13:53 volumiojca volumio[1263]: info: Received an update from plugin. extracting info from payload Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::pushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreCommandRouter::volumioPushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::pushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreCommandRouter::volumioPushState Oct 11 11:13:53 volumiojca volumio[1263]: info: ------------------------------ 19ms Oct 11 11:13:53 volumiojca volumio[1263]: info: sendMpdCommand playlistinfo took 14 milliseconds Oct 11 11:13:53 volumiojca volumio[1263]: info: sendMpdCommand playlistinfo took 14 milliseconds Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::parseTrackInfo Oct 11 11:13:53 volumiojca volumio[1263]: verbose: ControllerMpd::parseTrackInfo Oct 11 11:13:53 volumiojca volumio[1263]: info: ControllerMpd::pushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreCommandRouter::servicePushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:53 volumiojca volumio[1263]: verbose: STATE SERVICE {"status":"play","position":0,"seek":7,"duration":78,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2545 Kbps","isStreaming":false,"title":"25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous","artist":"C COIN","album":"Les Folies de Cardenio","uri":"USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/Lalande - Les Folies de Cardenio C COIN/25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous.flac","trackType":"flac"} Oct 11 11:13:53 volumiojca volumio[1263]: verbose: CURRENT POSITION 7 Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::syncState stateService play Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:13:53 volumiojca volumio[1263]: info: Received an update from plugin. extracting info from payload Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::pushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreCommandRouter::volumioPushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::pushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreCommandRouter::volumioPushState Oct 11 11:13:53 volumiojca volumio[1263]: info: ControllerMpd::pushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreCommandRouter::servicePushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:53 volumiojca volumio[1263]: verbose: STATE SERVICE {"status":"play","position":0,"seek":7,"duration":78,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2545 Kbps","isStreaming":false,"title":"25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous","artist":"C COIN","album":"Les Folies de Cardenio","uri":"USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/Lalande - Les Folies de Cardenio C COIN/25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous.flac","trackType":"flac"} Oct 11 11:13:53 volumiojca volumio[1263]: verbose: CURRENT POSITION 7 Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::syncState stateService play Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:13:53 volumiojca volumio[1263]: info: Received an update from plugin. extracting info from payload Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::pushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreCommandRouter::volumioPushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreStateMachine::pushState Oct 11 11:13:53 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:13:53 volumiojca volumio[1263]: info: CoreCommandRouter::volumioPushState Oct 11 11:13:53 volumiojca volumio[1263]: info: ------------------------------ 53ms Oct 11 11:13:53 volumiojca volumio[1263]: info: ------------------------------ 53ms Oct 11 11:14:14 volumiojca systemd[1]: Starting apt-daily-upgrade.service - Daily apt upgrade and clean activities... Oct 11 11:14:14 volumiojca systemd[1]: apt-daily-upgrade.service: Deactivated successfully. Oct 11 11:14:14 volumiojca systemd[1]: Finished apt-daily-upgrade.service - Daily apt upgrade and clean activities. Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.338+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.60:50803 Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.472+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.1.60:50803 @ 0x2000300" latency=239.905775ms timeout=20s Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.473+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" Oct 11 11:14:26 volumiojca volumio[1263]: info: Received Get System Info Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 11 11:14:26 volumiojca volumio[1263]: info: Discovery: Getting this device information Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::volumioGetState Oct 11 11:14:26 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.476+02:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" name=VolumioJCA Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.476+02:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" language=en Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.478+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" timezone=Europe/Paris Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.479+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" available=true connected=false macAddress= ip4Address= ip6Address= Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.483+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" available=true connected=true macAddress=d8:3a:dd:02:96:ca ip4Address=192.168.1.96/24 ip6Address= ssid=Freebox-C3FFC9 Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.483+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" setupComplete=true Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 11:14:26 volumiojca volumio[1263]: amixer -c 0 info | grep "bcm2835 ALSA" Oct 11 11:14:26 volumiojca volumio[1263]: amixer -c 1 info | grep "bcm2835 Headphones" Oct 11 11:14:26 volumiojca volumio[1263]: Card sysdefault:1 'Headphones'/'bcm2835 Headphones' Oct 11 11:14:26 volumiojca volumio[1263]: amixer -c 2 info | grep "vc4-hdmi-0" Oct 11 11:14:26 volumiojca volumio[1263]: Card sysdefault:2 'vc4hdmi0'/'vc4-hdmi-0' Oct 11 11:14:26 volumiojca volumio[1263]: amixer -c 3 info | grep "vc4-hdmi-1" Oct 11 11:14:26 volumiojca volumio[1263]: Card sysdefault:3 'vc4hdmi1'/'vc4-hdmi-1' Oct 11 11:14:26 volumiojca volumio[1263]: amixer -c 4 info | grep "snd_rpi_hifiberry_dac" Oct 11 11:14:26 volumiojca volumio[1263]: Card sysdefault:4 'sndrpihifiberry'/'snd_rpi_hifiberry_dac' Oct 11 11:14:26 volumiojca volumio[1263]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 4 Oct 11 11:14:26 volumiojca volumio[1263]: /bin/sh: 1: /usr/local/bin/alsacap: not found Oct 11 11:14:26 volumiojca volumio[1263]: {"cmd":"/usr/local/bin/alsacap -C 4","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 4\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)"} Oct 11 11:14:26 volumiojca volumio[1263]: amixer -c 4 info | grep "Generic I2S DAC" Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.627+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" selectedOutputId=4 Oct 11 11:14:26 volumiojca volumio[1263]: info: Received Get System Info Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 11 11:14:26 volumiojca volumio[1263]: info: Discovery: Getting this device information Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::volumioGetState Oct 11 11:14:26 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.645+02:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" currentVersion=4.119 latestVersion=4.119 Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.646+02:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.1.60:50803 @ 0x2000300" status=UPDATE_STATUS_NONE progress=0 Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.646+02:00 level=INFO msg="emitting user changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" userId=ASxeDXFpgXfMx9CGAmgS2hptpcJ3 Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.646+02:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" providers=9 Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.646+02:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" plugins=77 Oct 11 11:14:26 volumiojca volumio[1263]: info: CoreCommandRouter::volumioGetState Oct 11 11:14:26 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.650+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" state=STATUS_PLAYING positionMs=33543 volume=100 Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.650+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.60:50803 @ 0x2000300" id="mnt/USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/Lalande - Les Folies de Cardenio C COIN/25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous.flac" title="25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous" Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.823+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.887+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=http://pushupdates.volumio.org duration=62.968729ms Oct 11 11:14:26 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:26.952+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=129.493905ms Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.046+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=https://securetoken.googleapis.com duration=222.202219ms Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.046+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=https://google.com duration=222.184719ms Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.051+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=https://www.googleapis.com duration=226.749374ms Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.079+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=255.180589ms Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.095+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=https://functions.volumio.cloud duration=271.126505ms Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.097+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=https://functions.volumio.cloud duration=273.906613ms Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.101+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=277.437765ms Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.127+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=303.341794ms Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.236+02:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=http://cddb.volumio.org duration=412.559977ms error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.266+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=https://database.volumio.cloud duration=441.503147ms Oct 11 11:14:27 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:27.336+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=244.012293ms timeout=10s endpoint=http://plugins.volumio.org duration=512.301873ms Oct 11 11:14:28 volumiojca volumio[1263]: verbose: New Socket.io Connection to 192.168.1.96 from 192.168.1.60 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 VolumioApp/6.260905.0 Engine version: 3 Transport: polling Total Clients: 5 Oct 11 11:14:28 volumiojca volumio[1263]: info: CoreCommandRouter::volumioGetState Oct 11 11:14:28 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:14:28 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 11 11:14:28 volumiojca volumio[1263]: info: Listing playlists Oct 11 11:14:28 volumiojca volumio[1263]: info: CoreCommandRouter::volumioGetQueue Oct 11 11:14:28 volumiojca volumio[1263]: info: CoreStateMachine::getQueue Oct 11 11:14:28 volumiojca volumio[1263]: info: CorePlayQueue::getQueue Oct 11 11:14:28 volumiojca volumio[1263]: info: CoreCommandRouter::volumioGetVisibleSources Oct 11 11:14:28 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.368+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.382+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=13.447674ms Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.391+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=http://pushupdates.volumio.org duration=22.748538ms Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.408+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=38.777064ms Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.409+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=40.047564ms Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.414+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=https://google.com duration=45.76961ms Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.482+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=https://securetoken.googleapis.com duration=113.750543ms Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.484+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=https://www.googleapis.com duration=115.559684ms Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.488+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=119.712568ms Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.498+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=https://database.volumio.cloud duration=129.34213ms Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.504+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=https://functions.volumio.cloud duration=135.572076ms Oct 11 11:14:28 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:28.510+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=https://functions.volumio.cloud duration=141.71158ms Oct 11 11:14:30 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:30.219+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=http://plugins.volumio.org duration=1.850272365s Oct 11 11:14:30 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:30.234+02:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50803 @ 0x2000300" latency=256.570176ms timeout=10s endpoint=http://cddb.volumio.org duration=1.864910337s error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 11 11:14:30 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 11 11:14:30 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 11 11:14:30 volumiojca volumio[1263]: info: Discovery: Getting this device information Oct 11 11:14:30 volumiojca volumio[1263]: info: CoreCommandRouter::volumioGetState Oct 11 11:14:30 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:14:30 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 11 11:14:30 volumiojca volumio[1263]: verbose: New Socket.io Connection to 192.168.1.96:3000 from 192.168.1.60 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Oct 11 11:14:30 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 11 11:14:30 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.347+02:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.60:50803 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.347+02:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.60:50803 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.355+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.60:50913 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.387+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.1.60:50913 @ 0x24391d0" latency=235.604283ms timeout=20s Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.387+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" Oct 11 11:14:31 volumiojca volumio[1263]: info: Received Get System Info Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 11 11:14:31 volumiojca volumio[1263]: info: Discovery: Getting this device information Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::volumioGetState Oct 11 11:14:31 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.391+02:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" name=VolumioJCA Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.391+02:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" language=en Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.393+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" timezone=Europe/Paris Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.394+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" available=true connected=false macAddress= ip4Address= ip6Address= Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.397+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.398+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" available=true connected=true macAddress=d8:3a:dd:02:96:ca ip4Address=192.168.1.96/24 ip6Address= ssid=Freebox-C3FFC9 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.398+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" setupComplete=true Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.411+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=13.783614ms Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.422+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=http://pushupdates.volumio.org duration=24.288905ms Oct 11 11:14:31 volumiojca volumio[1263]: amixer -c 0 info | grep "bcm2835 ALSA" Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.436+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=37.814855ms Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.438+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=40.481762ms Oct 11 11:14:31 volumiojca volumio[1263]: amixer -c 1 info | grep "bcm2835 Headphones" Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.451+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=https://google.com duration=53.556033ms Oct 11 11:14:31 volumiojca volumio[1263]: Card sysdefault:1 'Headphones'/'bcm2835 Headphones' Oct 11 11:14:31 volumiojca volumio[1263]: amixer -c 2 info | grep "vc4-hdmi-0" Oct 11 11:14:31 volumiojca volumio[1263]: Card sysdefault:2 'vc4hdmi0'/'vc4-hdmi-0' Oct 11 11:14:31 volumiojca volumio[1263]: amixer -c 3 info | grep "vc4-hdmi-1" Oct 11 11:14:31 volumiojca volumio[1263]: Card sysdefault:3 'vc4hdmi1'/'vc4-hdmi-1' Oct 11 11:14:31 volumiojca volumio[1263]: amixer -c 4 info | grep "snd_rpi_hifiberry_dac" Oct 11 11:14:31 volumiojca volumio[1263]: Card sysdefault:4 'sndrpihifiberry'/'snd_rpi_hifiberry_dac' Oct 11 11:14:31 volumiojca volumio[1263]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 4 Oct 11 11:14:31 volumiojca volumio[1263]: /bin/sh: 1: /usr/local/bin/alsacap: not found Oct 11 11:14:31 volumiojca volumio[1263]: {"cmd":"/usr/local/bin/alsacap -C 4","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 4\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)"} Oct 11 11:14:31 volumiojca volumio[1263]: amixer -c 4 info | grep "Generic I2S DAC" Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.518+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=https://www.googleapis.com duration=120.438983ms Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.518+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=https://securetoken.googleapis.com duration=120.759275ms Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.520+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=122.089552ms Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.524+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=https://functions.volumio.cloud duration=125.520132ms Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.527+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=https://functions.volumio.cloud duration=128.909156ms Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.535+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" selectedOutputId=4 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.541+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=https://database.volumio.cloud duration=143.373741ms Oct 11 11:14:31 volumiojca volumio[1263]: info: Received Get System Info Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 11 11:14:31 volumiojca volumio[1263]: info: Discovery: Getting this device information Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::volumioGetState Oct 11 11:14:31 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.554+02:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" currentVersion=4.119 latestVersion=4.119 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.555+02:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.1.60:50913 @ 0x24391d0" status=UPDATE_STATUS_NONE progress=0 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.555+02:00 level=INFO msg="emitting user changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" userId=ASxeDXFpgXfMx9CGAmgS2hptpcJ3 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.555+02:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" providers=9 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.556+02:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" plugins=77 Oct 11 11:14:31 volumiojca volumio[1263]: info: CoreCommandRouter::volumioGetState Oct 11 11:14:31 volumiojca volumio[1263]: info: CorePlayQueue::getTrack 7 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.560+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" state=STATUS_PLAYING positionMs=38409 volume=100 Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.560+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.60:50913 @ 0x24391d0" id="mnt/USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/Lalande - Les Folies de Cardenio C COIN/25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous.flac" title="25 Ensemble Baroque de Limoges, Christophe Coin - La Bergerie - Contredanse pour tous" Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.646+02:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=http://cddb.volumio.org duration=248.640186ms error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 11 11:14:31 volumiojca volumio5-onboarding[1893]: time=2026-10-11T11:14:31.691+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.60:50913 @ 0x24391d0" latency=241.20344ms timeout=10s endpoint=http://plugins.volumio.org duration=293.666827ms Oct 11 11:14:33 volumiojca bluealsa[982]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_47_F5_0A_A4_4E_7B, ...) Oct 11 11:14:47 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 11 11:14:47 volumiojca volumio[1263]: info: CURURI: music-library/USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/M-R DeLalande - Symphonies pour les Soupers du Roy Reyne Oct 11 11:14:48 volumiojca volumio[1263]: info: Preload queue cleared Oct 11 11:14:51 volumiojca volumio[1263]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 11 11:14:51 volumiojca volumio[1263]: info: CURURI: music-library/USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/M-R DeLalande - Symphonies pour les Soupers du Roy Reyne/CD2 Oct 11 11:14:51 volumiojca volumio[1263]: info: Preload queue cleared Oct 11 11:14:57 volumiojca volumio[1263]: info: CoreCommandRouter::volumioAddQueueItems Oct 11 11:14:57 volumiojca volumio[1263]: info: CoreStateMachine::addQueueItems Oct 11 11:14:57 volumiojca volumio[1263]: info: CorePlayQueue::addQueueItems Oct 11 11:14:57 volumiojca volumio[1263]: info: Preload queue cleared Oct 11 11:14:57 volumiojca volumio[1263]: info: Adding Item to queue: music-library/USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/M-R DeLalande - Symphonies pour les Soupers du Roy Reyne/CD2 Oct 11 11:14:57 volumiojca volumio[1263]: info: Exploding uri music-library/USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/M-R DeLalande - Symphonies pour les Soupers du Roy Reyne/CD2 in service mpd Oct 11 11:14:57 volumiojca volumio[1263]: info: ALBUMART /albumart?cacheid=871&web=//extralarge&path=%2Fmnt%2FUSB%2FVOLUMIO%2FCLASSICAL%2FCOMPOSER%2FDELALANDE%2FM-R%20DeLalande%20-%20Symphonies%20pour%20les%20Soupers%20du%20Roy%20Reyne%2FCD2%2FDeLalande%20-%20Symphonies%20pour%20les%20Soupers%20du%20Roy%20-%20La%20Simphonie%20du%20Marais%20CD2.flac&metadata=false Oct 11 11:14:57 volumiojca volumio[1263]: info: URI /mnt/USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/M-R DeLalande - Symphonies pour les Soupers du Roy Reyne/CD2/DeLalande - Symphonies pour les Soupers du Roy - La Simphonie du Marais CD2.flac Oct 11 11:14:57 volumiojca volumio[1263]: info: ALBUMART /albumart?cacheid=871&web=Michel-Richard%20Delalande/Symphonies%20pour%20les%20Soupers%20du%20Roy%20CD2/extralarge&path=%2Fmnt%2FUSB%2FVOLUMIO%2FCLASSICAL%2FCOMPOSER%2FDELALANDE%2FM-R%20DeLalande%20-%20Symphonies%20pour%20les%20Soupers%20du%20Roy%20Reyne%2FCD2%2FDeLalande%20-%20Symphonies%20pour%20les%20Soupers%20du%20Roy%20-%20La%20Simphonie%20du%20Marais%20CD2.flac.cue&metadata=false Oct 11 11:14:57 volumiojca volumio[1263]: info: URI /mnt/USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/M-R DeLalande - Symphonies pour les Soupers du Roy Reyne/CD2/DeLalande - Symphonies pour les Soupers du Roy - La Simphonie du Marais CD2.flac.cue Oct 11 11:14:57 volumiojca volumio[1263]: info: ALBUMART /albumart?cacheid=871&web=Michel-Richard%20Delalande/Symphonies%20pour%20les%20Soupers%20du%20Roy%20CD2/extralarge&path=%2Fmnt%2FUSB%2FVOLUMIO%2FCLASSICAL%2FCOMPOSER%2FDELALANDE%2FM-R%20DeLalande%20-%20Symphonies%20pour%20les%20Soupers%20du%20Roy%20Reyne%2FCD2%2FDeLalande%20-%20Symphonies%20pour%20les%20Soupers%20du%20Roy%20-%20La%20Simphonie%20du%20Marais%20CD2.flac.cue&metadata=false Oct 11 11:14:57 volumiojca volumio[1263]: info: URI /mnt/USB/VOLUMIO/CLASSICAL/COMPOSER/DELALANDE/M-R DeLalande - Symphonies pour les Soupers du Roy Reyne/CD2/DeLalande - Symphonies pour les Soupers du Roy - La Simphonie du Marais CD2.flac.cue Oct 11 11:14:57 volumiojca volumio[1263]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 11 11:14:57 volumiojca volumio[1263]: Error: Unable to resolve or reject the same promise twice Oct 11 11:14:57 volumiojca volumio[1263]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Oct 11 11:14:57 volumiojca volumio[1263]: at /volumio/app/plugins/music_service/mpd/index.js:2582:21 Oct 11 11:14:57 volumiojca volumio[1263]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Oct 11 11:14:57 volumiojca volumio[1263]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Oct 11 11:14:57 volumiojca volumio[1263]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Oct 11 11:14:57 volumiojca volumio[1263]: at Socket.emit (node:events:514:28) Oct 11 11:14:57 volumiojca volumio[1263]: at addChunk (node:internal/streams/readable:343:12) Oct 11 11:14:57 volumiojca volumio[1263]: at readableAddChunk (node:internal/streams/readable:312:11) Oct 11 11:14:57 volumiojca volumio[1263]: at Readable.push (node:internal/streams/readable:253:10) Oct 11 11:14:57 volumiojca volumio[1263]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) Oct 11 11:14:57 volumiojca volumio[1263]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 11 11:14:58 volumiojca sudo[7824]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-11 11:13' Oct 11 11:14:58 volumiojca sudo[7824]: 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"