Aug 31 22:31:04 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 35959. Aug 31 22:31:04 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:31:04 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:31:05 primo-plus upmpdcli[1968]: Could not open config: /tmp/upmpdcli.conf Aug 31 22:31:05 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 31 22:31:05 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.518+08:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.200:61956 Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.541+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.545+08:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.0.200:61956 @ 0x295a4b0" latency=71.845325ms timeout=20s Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.545+08:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" Aug 31 22:31:05 primo-plus volumio[1173]: info: Received Get System Info Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 22:31:05 primo-plus volumio[1173]: info: Discovery: Getting this device information Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.551+08:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" name="Primo Plus" Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.553+08:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" language=zh_TW Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.555+08:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" timezone=Asia/Taipei Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.556+08:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" available=true connected=false macAddress= ip4Address= ip6Address= Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.562+08:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" available=true connected=true macAddress=88:a2:9e:ba:0e:84 ip4Address=192.168.0.158/24 ip6Address= ssid="Huang 5G" Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.562+08:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" setupComplete=true Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.575+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=https://google.com duration=33.693999ms Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 22:31:05 primo-plus volumio[1173]: amixer -c 0 info | grep "es9039q2m" Aug 31 22:31:05 primo-plus volumio[1173]: Card sysdefault:0 'es9039q2m'/'es9039q2m' Aug 31 22:31:05 primo-plus volumio[1173]: amixer -c 0 info | grep "es9039q2m" Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.631+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=89.990354ms Aug 31 22:31:05 primo-plus volumio[1173]: Card sysdefault:0 'es9039q2m'/'es9039q2m' Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.637+08:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" selectedOutputId=0 Aug 31 22:31:05 primo-plus volumio[1173]: info: Received Get System Info Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 22:31:05 primo-plus volumio[1173]: info: Discovery: Getting this device information Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.646+08:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" currentVersion=4.164 latestVersion=4.164 Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.646+08:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" status=UPDATE_STATUS_NONE progress=0 Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.646+08:00 level=INFO msg="emitting user changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" userId= Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.646+08:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" providers=3 Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.647+08:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" plugins=20 Aug 31 22:31:05 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.649+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" state=STATUS_PLAYING positionMs=75843 volume=100 Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.649+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:61956 @ 0x295a4b0" id=tidal://song/3699245 title="Manhã De Carnaval" Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.648+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=https://www.googleapis.com duration=106.239429ms Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.726+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=184.566852ms Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.727+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=https://securetoken.googleapis.com duration=183.871216ms Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.754+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=https://functions.volumio.cloud duration=210.208545ms Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.754+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=https://functions.volumio.cloud duration=211.297359ms Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.802+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=http://pushupdates.volumio.org duration=260.223025ms Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.816+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=https://database.volumio.cloud duration=274.652779ms Aug 31 22:31:05 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:05.945+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=402.910111ms Aug 31 22:31:06 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:06.063+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=521.369886ms Aug 31 22:31:06 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:06.129+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=http://plugins.volumio.org duration=587.27854ms Aug 31 22:31:06 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:06.446+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:61956 @ 0x295a4b0" latency=72.00078ms timeout=10s endpoint=http://cddb.volumio.org duration=904.398095ms Aug 31 22:31:06 primo-plus volumio[1173]: verbose: New Socket.io Connection to 192.168.0.158 from 192.168.0.200 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: 8 Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetVisibleSources Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 31 22:31:06 primo-plus volumio[1173]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 31 22:31:06 primo-plus volumio[1173]: info: Received Get System Info Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 22:31:06 primo-plus volumio[1173]: info: Discovery: Getting this device information Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:06 primo-plus volumio[1173]: info: Listing playlists Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetQueue Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreStateMachine::getQueue Aug 31 22:31:06 primo-plus volumio[1173]: info: CorePlayQueue::getQueue Aug 31 22:31:06 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 31 22:31:08 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059, ...) Aug 31 22:31:08 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a, ...) Aug 31 22:31:08 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a/desc005c, ...) Aug 31 22:31:08 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d, ...) Aug 31 22:31:08 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d/desc005f, ...) Aug 31 22:31:08 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char0060, ...) Aug 31 22:31:09 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 22:31:09 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 22:31:09 primo-plus volumio[1173]: info: Discovery: Getting this device information Aug 31 22:31:09 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:09 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 22:31:09 primo-plus volumio[1173]: verbose: New Socket.io Connection to 192.168.0.158:3000 from 192.168.0.200 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Aug 31 22:31:09 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 31 22:31:09 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.010+08:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.0.200:61956 Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.011+08:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.0.200:61956 Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.018+08:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.200:62077 Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.058+08:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.0.200:62077 @ 0x27e85a0" latency=71.497721ms timeout=20s Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.058+08:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" Aug 31 22:31:11 primo-plus volumio[1173]: info: Received Get System Info Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 22:31:11 primo-plus volumio[1173]: info: Discovery: Getting this device information Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.063+08:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" name="Primo Plus" Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.065+08:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" language=zh_TW Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.068+08:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" timezone=Asia/Taipei Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.069+08:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" available=true connected=false macAddress= ip4Address= ip6Address= Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.075+08:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" available=true connected=true macAddress=88:a2:9e:ba:0e:84 ip4Address=192.168.0.158/24 ip6Address= ssid="Huang 5G" Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.075+08:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" setupComplete=true Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.076+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 22:31:11 primo-plus volumio[1173]: amixer -c 0 info | grep "es9039q2m" Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.114+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=https://google.com duration=36.718559ms Aug 31 22:31:11 primo-plus volumio[1173]: Card sysdefault:0 'es9039q2m'/'es9039q2m' Aug 31 22:31:11 primo-plus volumio[1173]: amixer -c 0 info | grep "es9039q2m" Aug 31 22:31:11 primo-plus volumio[1173]: Card sysdefault:0 'es9039q2m'/'es9039q2m' Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.160+08:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" selectedOutputId=0 Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.164+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=86.832334ms Aug 31 22:31:11 primo-plus volumio[1173]: info: Received Get System Info Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 22:31:11 primo-plus volumio[1173]: info: Discovery: Getting this device information Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.170+08:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" currentVersion=4.164 latestVersion=4.164 Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.171+08:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" status=UPDATE_STATUS_NONE progress=0 Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.171+08:00 level=INFO msg="emitting user changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" userId= Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.171+08:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" providers=3 Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.171+08:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" plugins=20 Aug 31 22:31:11 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.174+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" state=STATUS_PLAYING positionMs=81355 volume=100 Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.174+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" id=tidal://song/3699245 title="Manhã De Carnaval" Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.182+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=https://www.googleapis.com duration=105.639847ms Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.185+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=107.397909ms Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.186+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=106.775976ms Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.255+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=178.674601ms Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.265+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=https://securetoken.googleapis.com duration=188.286771ms Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.277+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=https://functions.volumio.cloud duration=199.857351ms Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.280+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=https://functions.volumio.cloud duration=202.633452ms Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.280+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=https://database.volumio.cloud duration=202.014407ms Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.335+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=http://pushupdates.volumio.org duration=258.024619ms Aug 31 22:31:11 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:11.450+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=http://plugins.volumio.org duration=372.419167ms Aug 31 22:31:12 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:12.124+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.481616ms timeout=10s endpoint=http://cddb.volumio.org duration=1.047431192s Aug 31 22:31:17 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:17.826+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s Aug 31 22:31:17 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:17.854+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=https://google.com duration=27.271276ms Aug 31 22:31:17 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:17.911+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=84.638816ms Aug 31 22:31:17 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 22:31:17 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 22:31:17 primo-plus volumio[1173]: info: Discovery: Getting this device information Aug 31 22:31:17 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:17 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 22:31:17 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:17.932+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=https://www.googleapis.com duration=105.46272ms Aug 31 22:31:17 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:17.936+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=108.934105ms Aug 31 22:31:17 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:17.936+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=109.999087ms Aug 31 22:31:17 primo-plus volumio[1173]: verbose: New Socket.io Connection to 192.168.0.158:3000 from 192.168.0.200 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Aug 31 22:31:17 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 31 22:31:17 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 31 22:31:17 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a/desc005c, ...) Aug 31 22:31:17 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a, ...) Aug 31 22:31:17 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d/desc005f, ...) Aug 31 22:31:17 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d, ...) Aug 31 22:31:17 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char0060, ...) Aug 31 22:31:17 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059, ...) Aug 31 22:31:18 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:18.002+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=https://securetoken.googleapis.com duration=175.476377ms Aug 31 22:31:18 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:18.008+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=181.096856ms Aug 31 22:31:18 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:18.017+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=https://functions.volumio.cloud duration=190.356143ms Aug 31 22:31:18 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:18.018+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=https://functions.volumio.cloud duration=191.152166ms Aug 31 22:31:18 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:18.035+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=https://database.volumio.cloud duration=207.645422ms Aug 31 22:31:18 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:18.086+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=http://pushupdates.volumio.org duration=258.90501ms Aug 31 22:31:18 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:18.199+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=http://plugins.volumio.org duration=371.498516ms Aug 31 22:31:18 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:31:18.278+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=81.841734ms timeout=10s endpoint=http://cddb.volumio.org duration=450.498502ms Aug 31 22:31:19 primo-plus volumio[1173]: verbose: New Socket.io Connection to 192.168.0.158 from 192.168.0.200 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: 8 Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetVisibleSources Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 31 22:31:19 primo-plus volumio[1173]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 31 22:31:19 primo-plus volumio[1173]: info: Received Get System Info Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 22:31:19 primo-plus volumio[1173]: info: Discovery: Getting this device information Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:31:19 primo-plus volumio[1173]: info: Listing playlists Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetQueue Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreStateMachine::getQueue Aug 31 22:31:19 primo-plus volumio[1173]: info: CorePlayQueue::getQueue Aug 31 22:31:19 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 31 22:31:20 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 35960. Aug 31 22:31:20 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:31:20 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:31:20 primo-plus upmpdcli[2033]: Could not open config: /tmp/upmpdcli.conf Aug 31 22:31:20 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 31 22:31:20 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 31 22:31:27 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 31 22:31:27 primo-plus volumio[1173]: info: CURURI: playlists Aug 31 22:31:27 primo-plus volumio[1173]: info: Listing playlists Aug 31 22:31:27 primo-plus volumio[1173]: info: Preload queue cleared Aug 31 22:31:33 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 31 22:31:33 primo-plus volumio[1173]: info: Preload queue cleared Aug 31 22:31:35 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 35961. Aug 31 22:31:35 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:31:35 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:31:35 primo-plus upmpdcli[2051]: Could not open config: /tmp/upmpdcli.conf Aug 31 22:31:35 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 31 22:31:35 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 31 22:31:42 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059, ...) Aug 31 22:31:42 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a, ...) Aug 31 22:31:42 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a/desc005c, ...) Aug 31 22:31:42 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d, ...) Aug 31 22:31:42 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d/desc005f, ...) Aug 31 22:31:42 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char0060, ...) Aug 31 22:31:49 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a/desc005c, ...) Aug 31 22:31:49 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a, ...) Aug 31 22:31:49 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d/desc005f, ...) Aug 31 22:31:49 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d, ...) Aug 31 22:31:49 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char0060, ...) Aug 31 22:31:49 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059, ...) Aug 31 22:31:50 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 35962. Aug 31 22:31:50 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:31:50 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:31:50 primo-plus upmpdcli[2082]: Could not open config: /tmp/upmpdcli.conf Aug 31 22:31:50 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 31 22:31:50 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 31 22:31:51 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059, ...) Aug 31 22:31:51 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a, ...) Aug 31 22:31:51 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a/desc005c, ...) Aug 31 22:31:51 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d, ...) Aug 31 22:31:51 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d/desc005f, ...) Aug 31 22:31:51 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char0060, ...) Aug 31 22:32:05 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 35963. Aug 31 22:32:05 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:32:05 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:32:06 primo-plus upmpdcli[2100]: Could not open config: /tmp/upmpdcli.conf Aug 31 22:32:06 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 31 22:32:06 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 31 22:32:21 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 35964. Aug 31 22:32:21 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:32:21 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:32:21 primo-plus upmpdcli[2147]: Could not open config: /tmp/upmpdcli.conf Aug 31 22:32:21 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 31 22:32:21 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.095+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.126+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=https://google.com duration=30.064172ms Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.191+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=96.101213ms Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.201+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=https://www.googleapis.com duration=104.843304ms Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.203+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=107.463982ms Aug 31 22:32:34 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a/desc005c, ...) Aug 31 22:32:34 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a, ...) Aug 31 22:32:34 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d/desc005f, ...) Aug 31 22:32:34 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d, ...) Aug 31 22:32:34 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char0060, ...) Aug 31 22:32:34 primo-plus bluealsa[978]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059, ...) Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.277+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=https://securetoken.googleapis.com duration=180.658974ms Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.321+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=https://functions.volumio.cloud duration=223.016808ms Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.321+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=https://functions.volumio.cloud duration=223.528854ms Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.353+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=http://pushupdates.volumio.org duration=257.330055ms Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.454+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=https://database.volumio.cloud duration=355.733655ms Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.539+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=442.21892ms Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.699+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=604.067715ms Aug 31 22:32:34 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:34.706+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=http://plugins.volumio.org duration=607.686802ms Aug 31 22:32:34 primo-plus volumio[1173]: verbose: New Socket.io Connection to 192.168.0.158 from 192.168.0.200 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: 8 Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetVisibleSources Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 31 22:32:34 primo-plus volumio[1173]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 31 22:32:34 primo-plus volumio[1173]: info: Received Get System Info Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 22:32:34 primo-plus volumio[1173]: info: Discovery: Getting this device information Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:32:34 primo-plus volumio[1173]: info: Listing playlists Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetQueue Aug 31 22:32:34 primo-plus volumio[1173]: info: CoreStateMachine::getQueue Aug 31 22:32:34 primo-plus volumio[1173]: info: CorePlayQueue::getQueue Aug 31 22:32:35 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:35.012+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.200:62077 @ 0x27e85a0" latency=75.099165ms timeout=10s endpoint=http://cddb.volumio.org duration=916.226316ms Aug 31 22:32:35 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 31 22:32:36 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 35965. Aug 31 22:32:36 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:32:36 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 22:32:36 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 22:32:36 primo-plus volumio[1173]: info: Discovery: Getting this device information Aug 31 22:32:36 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:32:36 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 22:32:36 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 22:32:36 primo-plus volumio[1173]: verbose: New Socket.io Connection to 192.168.0.158:3000 from 192.168.0.200 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Aug 31 22:32:36 primo-plus upmpdcli[2165]: Could not open config: /tmp/upmpdcli.conf Aug 31 22:32:36 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 31 22:32:36 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 31 22:32:36 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 31 22:32:36 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 31 22:32:37 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 22:32:37 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 31 22:32:39 primo-plus volumio[1173]: info: Enabling plugin spop Aug 31 22:32:39 primo-plus volumio[1173]: info: Loading plugin "spop"... Aug 31 22:32:40 primo-plus volumio[1173]: info: PLUGIN START: spop Aug 31 22:32:40 primo-plus volumio[1173]: info: Creating Spotify config file Aug 31 22:32:40 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 22:32:40 primo-plus volumio[1173]: info: Done. Aug 31 22:32:40 primo-plus volumio[1173]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 22:32:40 primo-plus volumio[1173]: info: Spotify config file written Aug 31 22:32:40 primo-plus volumio[1173]: info: No need to fix Spotify hosts Aug 31 22:32:40 primo-plus sudo[2183]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 31 22:32:40 primo-plus sudo[2183]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 22:32:40 primo-plus systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 31 22:32:40 primo-plus systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 31 22:32:40 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 22:32:40 primo-plus go-librespot[2185]: go-librespot daemon starting... Aug 31 22:32:40 primo-plus sudo[2183]: pam_unix(sudo:session): session closed for user root Aug 31 22:32:41 primo-plus go-librespot[2186]: time="2026-08-31T22:32:41+08:00" level=info msg="running go-librespot 0.7.1" Aug 31 22:32:41 primo-plus go-librespot[2186]: time="2026-08-31T22:32:41+08:00" level=debug msg="app state loaded" Aug 31 22:32:41 primo-plus go-librespot[2186]: time="2026-08-31T22:32:41+08:00" level=debug msg="stored credentials not found" Aug 31 22:32:41 primo-plus go-librespot[2186]: time="2026-08-31T22:32:41+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 22:32:41 primo-plus volumio[1173]: info: New Spotify access tokenBQAgSpNFaM... Aug 31 22:32:41 primo-plus volumio[1173]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 31 22:32:41 primo-plus go-librespot[2186]: time="2026-08-31T22:32:41+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 31 22:32:41 primo-plus go-librespot[2186]: time="2026-08-31T22:32:41+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 31 22:32:41 primo-plus go-librespot[2186]: time="2026-08-31T22:32:41+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 31 22:32:41 primo-plus go-librespot[2186]: time="2026-08-31T22:32:41+08:00" level=info msg="zeroconf server listening on port 38235" Aug 31 22:32:41 primo-plus go-librespot[2186]: time="2026-08-31T22:32:41+08:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 22:32:41 primo-plus volumio[1173]: SPOTIFY: User informations: {"account_id":"5nsZgnVIAl","country":"TW","display_name":"黃柏勛","email":"sweetchild0505@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/11155833586"},"followers":{"href":null,"total":29},"href":"https://api.spotify.com/v1/users/11155833586","id":"11155833586","images":[{"height":300,"url":"https://scontent-mrs2-1.xx.fbcdn.net/v/t39.30808-1/325243218_1388804191925385_4571018935575687877_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=100&ccb=1-7&_nc_sid=08baa4&_nc_ohc=3xXgnhD-3dgQ7kNvwGaA1m0&_nc_oc=Adp_MdtcHWZGSUibU2R1ES2KiK0d8_OQznkgexguADx--8hJd1Nc1Jl-V5c2KuD6Jgf_Sv8xTooMrMAHE71lTgaP&_nc_zt=24&_nc_ht=scontent-mrs2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=4REX4LQcjL0_3SA-eFmufg&_nc_tpa=Q5bMBQLw1to1g18focJHdD5vN9d6PLo3InTMDojj3foy7WGU2eAUKe4rZMGhLJvjHoGW5yXGkIAJ&oh=00_AQJcEpAtdtk18vvAo5Y0CDJvKRTNS3_3dOzyuqoP3tK-jg&oe=6A9B6E0F","width":300},{"height":64,"url":"https://scontent-mrs2-1.xx.fbcdn.net/v/t39.30808-1/325243218_1388804191925385_4571018935575687877_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=100&ccb=1-7&_nc_sid=28885b&_nc_ohc=3xXgnhD-3dgQ7kNvwGaA1m0&_nc_oc=Adp_MdtcHWZGSUibU2R1ES2KiK0d8_OQznkgexguADx--8hJd1Nc1Jl-V5c2KuD6Jgf_Sv8xTooMrMAHE71lTgaP&_nc_zt=24&_nc_ht=scontent-mrs2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=4REX4LQcjL0_3SA-eFmufg&_nc_tpa=Q5bMBQJOpy3TLd_Z1X6CL_IpAcjlMymJ8A9PN6qyaoMGvJfJzZf1mNm8ML2IuxstxSpogrsXMN3d&oh=00_AQJh16TyxWqrIQMROmEH_W-g5fm3YCX6zJhLOpjmwIoeEA&oe=6A9B6E0F","width":64}],"product":"premium","type":"user","uri":"spotify:user:11155833586"} Aug 31 22:32:41 primo-plus volumio[1173]: info: Spotify Successfully logged in Aug 31 22:32:41 primo-plus volumio[1173]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 22:32:41 primo-plus volumio[1173]: info: [1788186761388] CoreMusicLibrary::Adding element Spotify Aug 31 22:32:41 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 22:32:41 primo-plus volumio[1173]: Cannot find translation for source TIDAL Aug 31 22:32:41 primo-plus volumio[1173]: Cannot find translation for source Spotify Aug 31 22:32:43 primo-plus volumio[1173]: info: go-librespot daemon successfully initialized Aug 31 22:32:44 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059, ...) Aug 31 22:32:44 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a, ...) Aug 31 22:32:44 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005a/desc005c, ...) Aug 31 22:32:44 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d, ...) Aug 31 22:32:44 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char005d/desc005f, ...) Aug 31 22:32:44 primo-plus bluealsa[978]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_58_E3_2B_91_26_6C/service0059/char0060, ...) Aug 31 22:32:46 primo-plus go-librespot[2186]: time="2026-08-31T22:32:46+08:00" level=debug msg="obtained new client token: AAGVYg9EPZfQZl0FYCafdBwwSOU/6MAb5uppHHtFcNMKbGqUOBIfiArlucx0Z/uAxrycJcVkig6jLILOduCPvVwfn8ypgMo96ZCdhhEzJllFbTr4rc+2ZL8tf2B7mDkT6vdcIbovBoxIVqf4otFI09ltQA4+/9wRecZrpbKHhBXeigGv5zeOGIqXvQzRQeB+DztrtjsY0896vA2NdA1L6zG/Sw//mZV/bHogQl5/d+7XbTMHi0CrhX1Y" Aug 31 22:32:46 primo-plus go-librespot[2186]: time="2026-08-31T22:32:46+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 22:32:46 primo-plus go-librespot[2186]: time="2026-08-31T22:32:46+08:00" level=debug msg="completed keyexchange" Aug 31 22:32:46 primo-plus go-librespot[2186]: time="2026-08-31T22:32:46+08:00" level=debug msg="completed challenge" Aug 31 22:32:46 primo-plus go-librespot[2186]: time="2026-08-31T22:32:46+08:00" level=info msg="authenticated AP" username="11*******86" Aug 31 22:32:46 primo-plus volumio[1173]: info: Initializing connection to go-librespot Websocket Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="new websocket client" Aug 31 22:32:47 primo-plus volumio[1173]: info: Connection to go-librespot Websocket established Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=info msg="authenticated Login5" username="11*******86" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=info msg="accepted zeroconf from iPhone" username="11*******86" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="dealer connection opened" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="starting accesspoint recv loop" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="starting dealer recv loop" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="received accesspoint ping" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="received connection id: ZjY0ZDE0ZmEtMWVm...MDhCRDdGMjk0Qg==" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="received accesspoint pong ack" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="put connect state because NEW_DEVICE" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="update volume requested to 0/65535" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="handling transfer player command from 3dfb8e37375281beaa5f6c6098b2f6ee862ca8b9" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="resolved context of track" uri="spotify:playlist:51kf85uSngtedY8NQIv1QI" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="fetched new page 0 with 18 items (list: 18)" uri="spotify:playlist:51kf85uSngtedY8NQIv1QI" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="loading track (paused: true, position: 13247ms)" uri="spotify:track:0JUWF44gfMszGNhjCF7Ufs" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="emitting websocket event: will_play" Aug 31 22:32:47 primo-plus volumio[1173]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:51kf85uSngtedY8NQIv1QI","uri":"spotify:track:0JUWF44gfMszGNhjCF7Ufs","play_origin":"playlist/ondemand"}} Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 438" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="selected format OGG_VORBIS_96 (e38f7fea9cdcf348f53cff87b21c59f5ce2d4457)" uri="spotify:track:0JUWF44gfMszGNhjCF7Ufs" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="requested aes key for file e38f7fea9cdcf348f53cff87b21c59f5ce2d4457, gid: 0JUWF44gfMszGNhjCF7Ufs" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0JUWF44gfMszGNhjCF7Ufs" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="fetched first chunk of 8, total size is 4106770 bytes" uri="spotify:track:0JUWF44gfMszGNhjCF7Ufs" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="seek to 13247ms (diff: 263ms, samples: 584192, bytes: 149520)" uri="spotify:track:0JUWF44gfMszGNhjCF7Ufs" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="created new output device" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=info msg="loaded track \"Midnight Pretenders\" (paused: true, position: 13247ms, duration: 345266ms, prefetched: false)" uri="spotify:track:0JUWF44gfMszGNhjCF7Ufs" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3635" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 438" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="fetched chunk 2/7, size: 524288" uri="spotify:track:0JUWF44gfMszGNhjCF7Ufs" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="emitting websocket event: metadata" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="emitting websocket event: active" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="sending successful reply for dealer request" Aug 31 22:32:47 primo-plus volumio[1173]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0JUWF44gfMszGNhjCF7Ufs","name":"Midnight Pretenders","artist_names":["Tomoko Aran"],"album_name":"浮遊空間","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027d2d24d8a6bf7578a140db55","position":13247,"duration":345266,"release_date":"year:1983","track_number":5,"disc_number":1}} Aug 31 22:32:47 primo-plus volumio[1173]: SPOTIFY: received: {"type":"active","data":null} Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 31 22:32:47 primo-plus volumio[1173]: info: Aligning Spotify Volume to Volumio Volume Aug 31 22:32:47 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:32:47 primo-plus volumio[1173]: info: Setting Spotify Volume from Volumio: 100 Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="emitting websocket event: volume" Aug 31 22:32:47 primo-plus volumio[1173]: SPOTIFY: received: {"type":"volume","data":{"value":0,"max":100}} Aug 31 22:32:47 primo-plus volumio[1173]: SPOTIFY: RECEIVED SPOTIFY VOLUME 0 Aug 31 22:32:47 primo-plus volumio[1173]: info: Setting Volumio Volume from Spotify: 0 Aug 31 22:32:47 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: inputs , alsavolume Aug 31 22:32:47 primo-plus volumio[1173]: info: CoreStateMachine::pushState Aug 31 22:32:47 primo-plus volumio[1173]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 22:32:47 primo-plus volumio[1173]: info: CoreCommandRouter::volumioPushState Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="fetched chunk 1/7, size: 524288" uri="spotify:track:0JUWF44gfMszGNhjCF7Ufs" Aug 31 22:32:47 primo-plus volumio[1173]: info: CoreCommandRouter::volumioGetState Aug 31 22:32:47 primo-plus volumio[1173]: info: MRS: Pushing multiroomSync output update for this device Aug 31 22:32:47 primo-plus volumio[1173]: info: MRS: Pushing multiroomSync output Aug 31 22:32:47 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:47.804+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" state=STATUS_PLAYING positionMs=177955 volume=0 Aug 31 22:32:47 primo-plus volumio5-onboarding[1931]: time=2026-08-31T22:32:47.805+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:62077 @ 0x27e85a0" id=tidal://song/3699245 title="Manhã De Carnaval" Aug 31 22:32:47 primo-plus volumio[1173]: info: Signalling Playback active due to playback status change Aug 31 22:32:47 primo-plus volumio[1173]: info: Updating RAAT Signal Path Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=trace msg="emitting websocket event: paused" Aug 31 22:32:47 primo-plus volumio[1173]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:51kf85uSngtedY8NQIv1QI","uri":"spotify:track:0JUWF44gfMszGNhjCF7Ufs","play_origin":"playlist/ondemand"}} Aug 31 22:32:47 primo-plus volumio[1173]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 22:32:47 primo-plus volumio[1173]: TypeError: Cannot read properties of undefined (reading 'service') Aug 31 22:32:47 primo-plus volumio[1173]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Aug 31 22:32:47 primo-plus volumio[1173]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Aug 31 22:32:47 primo-plus volumio[1173]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Aug 31 22:32:47 primo-plus volumio[1173]: at WebSocket.emit (node:events:514:28) Aug 31 22:32:47 primo-plus volumio[1173]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Aug 31 22:32:47 primo-plus volumio[1173]: at Receiver.emit (node:events:514:28) Aug 31 22:32:47 primo-plus volumio[1173]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Aug 31 22:32:47 primo-plus volumio[1173]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Aug 31 22:32:47 primo-plus volumio[1173]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Aug 31 22:32:47 primo-plus volumio[1173]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Aug 31 22:32:47 primo-plus volumio[1173]: at writeOrBuffer (node:internal/streams/writable:399:12) Aug 31 22:32:47 primo-plus volumio[1173]: at _write (node:internal/streams/writable:340:10) Aug 31 22:32:47 primo-plus volumio[1173]: at Writable.write (node:internal/streams/writable:344:10) Aug 31 22:32:47 primo-plus volumio[1173]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Aug 31 22:32:47 primo-plus volumio[1173]: at Socket.emit (node:events:514:28) Aug 31 22:32:47 primo-plus volumio[1173]: at addChunk (node:internal/streams/readable:343:12) Aug 31 22:32:47 primo-plus volumio[1173]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="fetched chunk 3/7, size: 524288" uri="spotify:track:0JUWF44gfMszGNhjCF7Ufs" Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 31 22:32:47 primo-plus go-librespot[2186]: time="2026-08-31T22:32:47+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2321" Aug 31 22:32:48 primo-plus sudo[2210]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-31 22:31' Aug 31 22:32:48 primo-plus sudo[2210]: 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"