Oct 14 22:36:02 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 7804. Oct 14 22:36:02 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:36:02 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:36:02 primo-plus upmpdcli[32618]: Could not open config: /tmp/upmpdcli.conf Oct 14 22:36:02 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 14 22:36:02 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.129+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.267+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=138.079727ms Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.364+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=https://www.googleapis.com duration=232.917903ms Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.395+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=265.246059ms Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.395+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=https://google.com duration=264.510795ms Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.464+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=332.571139ms Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.464+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=https://securetoken.googleapis.com duration=334.41181ms Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.482+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=350.105303ms Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.554+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=https://functions.volumio.cloud duration=421.442718ms Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.554+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=https://functions.volumio.cloud duration=423.629364ms Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.642+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=https://database.volumio.cloud duration=509.324446ms Oct 14 22:36:17 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 7805. Oct 14 22:36:17 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:36:17 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:17.759+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=http://plugins.volumio.org duration=627.543661ms Oct 14 22:36:17 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:36:17 primo-plus upmpdcli[32633]: Could not open config: /tmp/upmpdcli.conf Oct 14 22:36:17 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 14 22:36:17 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 14 22:36:18 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:18.217+09:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=http://cddb.volumio.org duration=1.084071652s error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 14 22:36:18 primo-plus volumio[1158]: verbose: New Socket.io Connection to 192.168.40.55 from 192.168.40.37 UA: Mozilla/5.0 (Linux; Android 12; TB328FU Build/SP1A.210812.016; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/155.0.8059.43 Safari/537.36 VolumioApp/6.260930.0 Engine version: 3 Transport: polling Total Clients: 8 Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetVisibleSources Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:36:18 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 1 Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:36:18 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 1 Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 14 22:36:18 primo-plus volumio[1158]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Oct 14 22:36:18 primo-plus volumio[1158]: info: Received Get System Info Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 14 22:36:18 primo-plus volumio[1158]: info: Discovery: Getting this device information Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:36:18 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 1 Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:36:18 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 1 Oct 14 22:36:18 primo-plus volumio[1158]: info: Listing playlists Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetQueue Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreStateMachine::getQueue Oct 14 22:36:18 primo-plus volumio[1158]: info: CorePlayQueue::getQueue Oct 14 22:36:18 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 14 22:36:20 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:36:20.322+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" latency=4.514124903s timeout=10s endpoint=http://pushupdates.volumio.org duration=3.188208892s Oct 14 22:36:32 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 7806. Oct 14 22:36:32 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:36:33 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:36:33 primo-plus upmpdcli[32666]: Could not open config: /tmp/upmpdcli.conf Oct 14 22:36:33 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 14 22:36:33 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 14 22:36:40 primo-plus systemd[1]: Starting apt-daily.service - Daily apt download activities... Oct 14 22:36:41 primo-plus systemd[1]: apt-daily.service: Deactivated successfully. Oct 14 22:36:41 primo-plus systemd[1]: Finished apt-daily.service - Daily apt download activities. Oct 14 22:36:48 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 7807. Oct 14 22:36:48 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:36:48 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:36:48 primo-plus upmpdcli[32728]: Could not open config: /tmp/upmpdcli.conf Oct 14 22:36:48 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 14 22:36:48 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 14 22:37:03 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 7808. Oct 14 22:37:03 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:37:03 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:37:03 primo-plus upmpdcli[32758]: Could not open config: /tmp/upmpdcli.conf Oct 14 22:37:03 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 14 22:37:03 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 14 22:37:09 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 1 Oct 14 22:37:09 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:09 primo-plus volumio[1158]: info: Prefetching next song Oct 14 22:37:09 primo-plus volumio[1158]: info: [1791985029545] ControllerQobuz::prefetch Oct 14 22:37:10 primo-plus volumio[1158]: info: getStreamUrl took 612 milliseconds Oct 14 22:37:10 primo-plus volumio[1158]: verbose: ControllerMpd::sendMpdCommand load "https://streaming-qobuz-std.akamaized.net/file?uid=15337938&eid=245110481&fmt=6&profile=raw&app_id=539451548&cid=4718513&etsp=1791988629&hmac=WUBwhaVmhxfR1Pgp9iDRddjY0Y0" Oct 14 22:37:11 primo-plus volumio[1158]: verbose: ControllerMpd::sendMpdCommand add "https://streaming-qobuz-std.akamaized.net/file?uid=15337938&eid=245110481&fmt=6&profile=raw&app_id=539451548&cid=4718513&etsp=1791988629&hmac=WUBwhaVmhxfR1Pgp9iDRddjY0Y0" Oct 14 22:37:11 primo-plus volumio[1158]: info: sendMpdCommand add "https://streaming-qobuz-std.akamaized.net/file?uid=15337938&eid=245110481&fmt=6&profile=raw&app_id=539451548&cid=4718513&etsp=1791988629&hmac=WUBwhaVmhxfR1Pgp9iDRddjY0Y0" took 1 milliseconds Oct 14 22:37:11 primo-plus volumio[1158]: info: CoreStateMachine::setConsumeUpdateService mpd Oct 14 22:37:11 primo-plus volumio[1158]: verbose: ControllerMpd::sendMpdCommand consume 1 Oct 14 22:37:11 primo-plus volumio[1158]: info: Oct 14 22:37:11 primo-plus volumio[1158]: ---------------------------- MPD announces system playlist update Oct 14 22:37:11 primo-plus volumio[1158]: info: Ignoring MPD Status Update Oct 14 22:37:11 primo-plus volumio[1158]: info: sendMpdCommand consume 1 took 1 milliseconds Oct 14 22:37:11 primo-plus volumio[1158]: info: Oct 14 22:37:11 primo-plus volumio[1158]: ---------------------------- MPD announces system playlist update Oct 14 22:37:11 primo-plus volumio[1158]: info: Ignoring MPD Status Update Oct 14 22:37:11 primo-plus volumio[1158]: info: Oct 14 22:37:11 primo-plus volumio[1158]: ---------------------------- MPD announces system playlist update Oct 14 22:37:11 primo-plus volumio[1158]: info: Ignoring MPD Status Update Oct 14 22:37:11 primo-plus volumio[1158]: info: ------------------------------ 3ms Oct 14 22:37:11 primo-plus volumio[1158]: info: ------------------------------ 3ms Oct 14 22:37:11 primo-plus volumio[1158]: info: ------------------------------ 2ms Oct 14 22:37:14 primo-plus volumio[1158]: info: Oct 14 22:37:14 primo-plus volumio[1158]: ---------------------------- MPD announces system playlist update Oct 14 22:37:14 primo-plus volumio[1158]: info: Ignoring MPD Status Update Oct 14 22:37:14 primo-plus volumio[1158]: info: Oct 14 22:37:14 primo-plus volumio[1158]: ---------------------------- MPD announces state update: player Oct 14 22:37:14 primo-plus volumio[1158]: info: ControllerMpd::getState Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::sendMpdCommand status Oct 14 22:37:14 primo-plus volumio[1158]: info: Oct 14 22:37:14 primo-plus volumio[1158]: ---------------------------- MPD announces system playlist update Oct 14 22:37:14 primo-plus volumio[1158]: info: Ignoring MPD Status Update Oct 14 22:37:14 primo-plus volumio[1158]: info: Oct 14 22:37:14 primo-plus volumio[1158]: ---------------------------- MPD announces state update: player Oct 14 22:37:14 primo-plus volumio[1158]: info: ControllerMpd::getState Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::sendMpdCommand status Oct 14 22:37:14 primo-plus volumio[1158]: info: Oct 14 22:37:14 primo-plus volumio[1158]: ---------------------------- MPD announces system playlist update Oct 14 22:37:14 primo-plus volumio[1158]: info: Ignoring MPD Status Update Oct 14 22:37:14 primo-plus volumio[1158]: info: Oct 14 22:37:14 primo-plus volumio[1158]: ---------------------------- MPD announces state update: player Oct 14 22:37:14 primo-plus volumio[1158]: info: ControllerMpd::getState Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::sendMpdCommand status Oct 14 22:37:14 primo-plus volumio[1158]: info: ------------------------------ 5ms Oct 14 22:37:14 primo-plus volumio[1158]: info: sendMpdCommand status took 4 milliseconds Oct 14 22:37:14 primo-plus volumio[1158]: info: ------------------------------ 3ms Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::parseState Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 14 22:37:14 primo-plus volumio[1158]: info: sendMpdCommand status took 5 milliseconds Oct 14 22:37:14 primo-plus volumio[1158]: info: ------------------------------ 4ms Oct 14 22:37:14 primo-plus volumio[1158]: info: sendMpdCommand status took 3 milliseconds Oct 14 22:37:14 primo-plus volumio[1158]: info: sendMpdCommand playlistinfo took 1 milliseconds Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::parseState Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::parseState Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::parseTrackInfo Oct 14 22:37:14 primo-plus volumio[1158]: info: ControllerMpd::pushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::servicePushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 1 Oct 14 22:37:14 primo-plus volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":201,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"740 Kbps","isStreaming":false,"title":"file?uid=15337938&eid=245110481&fmt=6&profile=raw&app_id=539451548&cid=4718513&etsp=1791988629&hmac=WUBwhaVmhxfR1Pgp9iDRddjY0Y0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=15337938&eid=245110481&fmt=6&profile=raw&app_id=539451548&cid=4718513&etsp=1791988629&hmac=WUBwhaVmhxfR1Pgp9iDRddjY0Y0","trackType":"qobuz"} Oct 14 22:37:14 primo-plus volumio[1158]: verbose: CURRENT POSITION 1 Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::syncState stateService play Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::syncState currentStatus play Oct 14 22:37:14 primo-plus volumio[1158]: info: Received an update from plugin. extracting info from payload Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::pushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioPushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output update for this device Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::pushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioPushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output update for this device Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.033+09:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" state=STATUS_PLAYING positionMs=174281 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.034+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" state=STATUS_PLAYING positionMs=174281 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.034+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" state=STATUS_PLAYING positionMs=174281 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.034+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" id=qobuz://song/245110480 title="Caprice in B minor, Op. 1, No. 2" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.034+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" id=qobuz://song/245110480 title="Caprice in B minor, Op. 1, No. 2" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.034+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" id=qobuz://song/245110480 title="Caprice in B minor, Op. 1, No. 2" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.037+09:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" state=STATUS_PLAYING positionMs=174281 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.037+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" state=STATUS_PLAYING positionMs=174281 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.037+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" state=STATUS_PLAYING positionMs=174281 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.037+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" id=qobuz://song/245110480 title="Caprice in B minor, Op. 1, No. 2" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.038+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" id=qobuz://song/245110480 title="Caprice in B minor, Op. 1, No. 2" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.038+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" id=qobuz://song/245110480 title="Caprice in B minor, Op. 1, No. 2" Oct 14 22:37:14 primo-plus volumio[1158]: info: ------------------------------ 37ms Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::startPlaybackTimer Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: sendMpdCommand playlistinfo took 31 milliseconds Oct 14 22:37:14 primo-plus volumio[1158]: info: sendMpdCommand playlistinfo took 30 milliseconds Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::parseTrackInfo Oct 14 22:37:14 primo-plus volumio[1158]: verbose: ControllerMpd::parseTrackInfo Oct 14 22:37:14 primo-plus volumio[1158]: info: ControllerMpd::pushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::servicePushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":201,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"740 Kbps","isStreaming":false,"title":"file?uid=15337938&eid=245110481&fmt=6&profile=raw&app_id=539451548&cid=4718513&etsp=1791988629&hmac=WUBwhaVmhxfR1Pgp9iDRddjY0Y0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=15337938&eid=245110481&fmt=6&profile=raw&app_id=539451548&cid=4718513&etsp=1791988629&hmac=WUBwhaVmhxfR1Pgp9iDRddjY0Y0","trackType":"qobuz"} Oct 14 22:37:14 primo-plus volumio[1158]: verbose: CURRENT POSITION 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::syncState stateService play Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::syncState currentStatus play Oct 14 22:37:14 primo-plus volumio[1158]: info: Received an update from plugin. extracting info from payload Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::pushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioPushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output update for this device Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::pushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioPushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output update for this device Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output Oct 14 22:37:14 primo-plus volumio[1158]: info: ControllerMpd::pushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::servicePushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":201,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"740 Kbps","isStreaming":false,"title":"file?uid=15337938&eid=245110481&fmt=6&profile=raw&app_id=539451548&cid=4718513&etsp=1791988629&hmac=WUBwhaVmhxfR1Pgp9iDRddjY0Y0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=15337938&eid=245110481&fmt=6&profile=raw&app_id=539451548&cid=4718513&etsp=1791988629&hmac=WUBwhaVmhxfR1Pgp9iDRddjY0Y0","trackType":"qobuz"} Oct 14 22:37:14 primo-plus volumio[1158]: verbose: CURRENT POSITION 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::syncState stateService play Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::syncState currentStatus play Oct 14 22:37:14 primo-plus volumio[1158]: info: Received an update from plugin. extracting info from payload Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::pushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioPushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output update for this device Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::pushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioPushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output update for this device Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.069+09:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.069+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.070+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.070+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.070+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.070+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.070+09:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.071+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.071+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.071+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.071+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.071+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.076+09:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.076+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.076+09:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.076+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.076+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.076+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" state=STATUS_PLAYING positionMs=0 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.077+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.077+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.077+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.077+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.077+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.077+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio[1158]: info: ------------------------------ 70ms Oct 14 22:37:14 primo-plus volumio[1158]: info: ------------------------------ 70ms Oct 14 22:37:14 primo-plus volumio[1158]: info: Signalling Playback active due to playback status change Oct 14 22:37:14 primo-plus volumio[1158]: info: Signalling Playback active due to playback status change Oct 14 22:37:14 primo-plus volumio[1158]: info: Signalling Playback active due to playback status change Oct 14 22:37:14 primo-plus volumio[1158]: info: Signalling Playback active due to playback status change Oct 14 22:37:14 primo-plus volumio[1158]: info: Signalling Playback active due to playback status change Oct 14 22:37:14 primo-plus volumio[1158]: info: Signalling Playback active due to playback status change Oct 14 22:37:14 primo-plus volumio[1158]: info: Updating RAAT Signal Path Oct 14 22:37:14 primo-plus volumio[1158]: info: Updating RAAT Signal Path Oct 14 22:37:14 primo-plus volumio[1158]: info: Updating RAAT Signal Path Oct 14 22:37:14 primo-plus volumio[1158]: info: Updating RAAT Signal Path Oct 14 22:37:14 primo-plus volumio[1158]: info: Updating RAAT Signal Path Oct 14 22:37:14 primo-plus volumio[1158]: info: Updating RAAT Signal Path Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreStateMachine::pushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioPushState Oct 14 22:37:14 primo-plus volumio[1158]: info: CoreCommandRouter::volumioGetState Oct 14 22:37:14 primo-plus volumio[1158]: info: CorePlayQueue::getTrack 2 Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output update for this device Oct 14 22:37:14 primo-plus volumio[1158]: info: MRS: Pushing multiroomSync output Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.578+09:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" state=STATUS_PLAYING positionMs=500 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.580+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" state=STATUS_PLAYING positionMs=500 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.581+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" state=STATUS_PLAYING positionMs=500 volume=100 Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.582+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%07,192.168.40.37:42520 @ 0x38a8870" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.583+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.40:53036 @ 0x38a9320" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio5-onboarding[1953]: time=2026-10-14T22:37:14.584+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.40.37:42520 @ 0x34d5890" id=qobuz://song/245110481 title="Caprice in E minor, Op. 1, No. 3" Oct 14 22:37:14 primo-plus volumio[1158]: info: Signalling Playback active due to playback status change Oct 14 22:37:14 primo-plus volumio[1158]: info: Updating RAAT Signal Path Oct 14 22:37:18 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 7809. Oct 14 22:37:18 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:37:18 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 14 22:37:18 primo-plus upmpdcli[318]: Could not open config: /tmp/upmpdcli.conf Oct 14 22:37:18 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 14 22:37:18 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 14 22:37:30 primo-plus volumio[1158]: info: CoreCommandRouter::executeOnPlugin: metavolumio , superSearch Oct 14 22:37:30 primo-plus volumio[1158]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 14 22:37:30 primo-plus volumio[1158]: TypeError: Cannot read properties of undefined (reading 'then') Oct 14 22:37:30 primo-plus volumio[1158]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:498:20) Oct 14 22:37:30 primo-plus volumio[1158]: at Socket.emit (node:events:514:28) Oct 14 22:37:30 primo-plus volumio[1158]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Oct 14 22:37:30 primo-plus volumio[1158]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Oct 14 22:37:30 primo-plus volumio[1158]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 14 22:37:31 primo-plus sudo[348]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-14 22:36' Oct 14 22:37:31 primo-plus sudo[348]: 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="ceea798be624bcca033d94ae449c2a749a9724f0" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="9938d7179e3b7c4e41f3e2d60c255985cff08fee" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="primoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed May 27 09:37:15 UTC 2026" VOLUMIO_VERSION="4.164" VOLUMIO_HARDWARE="cm4" VOLUMIO_DEVICENAME="CM4" VOLUMIO_VENDOR_MODEL="Volumio Primo Plus" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo Plus" VOLUMIO_HASH="c8e7083e83ff605518b1cfc23784b0e7"