-- Logs begin at Mon 2026-03-16 12:43:08 JST, end at Sat 2026-03-28 15:42:38 JST. -- Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.664+09:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.11:51464 Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.717+09:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.0.11:51464 @ 0x14c4600" latency=6.559621ms timeout=10s Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.717+09:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.718+09:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.0.11:51464 @ 0x14c4600" latency=8.34483ms platform=PLATFORM_IOS version=5.260209.0 Mar 28 15:41:08 rivoplus volumio[3188]: info: Received Get System Info Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 15:41:08 rivoplus volumio[3188]: info: Discovery: Getting this device information Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.723+09:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" name=Rivoplus Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.724+09:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" language=ja Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.728+09:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" timezone=Asia/Tokyo Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.730+09:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" available=true connected=true macAddress=02:00:00:28:13:01 ip4Address=192.168.0.4/24 ip6Address= Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.734+09:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.734+09:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" setupComplete=true Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Mar 28 15:41:08 rivoplus volumio[3188]: No protocol specified Mar 28 15:41:08 rivoplus volumio[3188]: xcb_connection_has_error() returned true Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 28 15:41:08 rivoplus volumio[3188]: amixer -c 5 info | grep "Comtrue-inc UAC2 Device" Mar 28 15:41:08 rivoplus volumio[3188]: No protocol specified Mar 28 15:41:08 rivoplus volumio[3188]: xcb_connection_has_error() returned true Mar 28 15:41:08 rivoplus volumio[3188]: Card hw:5 'Device'/'Comtrue-inc Comtrue-inc UAC2 Device at usb-xhci-hcd.0.auto-1.4.3, high speed' Mar 28 15:41:08 rivoplus volumio[3188]: amixer -c 5 info | grep "Comtrue-inc UAC2 Device" Mar 28 15:41:08 rivoplus volumio[3188]: No protocol specified Mar 28 15:41:08 rivoplus volumio[3188]: xcb_connection_has_error() returned true Mar 28 15:41:08 rivoplus volumio[3188]: Card hw:5 'Device'/'Comtrue-inc Comtrue-inc UAC2 Device at usb-xhci-hcd.0.auto-1.4.3, high speed' Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.971+09:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" selectedOutputId=5 Mar 28 15:41:08 rivoplus volumio[3188]: info: Received Get System Info Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 15:41:08 rivoplus volumio[3188]: info: Discovery: Getting this device information Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.983+09:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" currentVersion=3.912 latestVersion=3.912 Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.983+09:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.0.11:51464 @ 0x14c4600" status=UPDATE_STATUS_NONE progress=0 Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.983+09:00 level=INFO msg="emitting user changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" userId= Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.984+09:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" providers=3 Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.984+09:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" plugins=26 Mar 28 15:41:08 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.989+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" state=STATUS_PLAYING positionMs=93486000 volume=100 Mar 28 15:41:08 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:08.990+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.11:51464 @ 0x14c4600" id= title= Mar 28 15:41:09 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 15:41:09 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 15:41:09 rivoplus volumio[3188]: info: Discovery: Getting this device information Mar 28 15:41:09 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:41:09 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 15:41:09 rivoplus volumio[3188]: verbose: New Socket.io Connection to 192.168.0.4:3000 from 192.168.0.11 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Mar 28 15:41:10 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 15:41:10 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 15:41:10 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:10.445+09:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.11:51464 @ 0x14c4600" latency=4.982675ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Mar 28 15:41:10 rivoplus sudo[15900]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 15:41:10 rivoplus sudo[15900]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 28 15:41:10 rivoplus sudo[15900]: pam_unix(sudo:session): session closed for user root Mar 28 15:41:10 rivoplus sudo[15904]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 15:41:10 rivoplus sudo[15904]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 28 15:41:10 rivoplus sudo[15904]: pam_unix(sudo:session): session closed for user root Mar 28 15:41:10 rivoplus volumio[3188]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.11 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: 9 Mar 28 15:41:10 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 28 15:41:11 rivoplus sudo[15908]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 15:41:11 rivoplus sudo[15908]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 28 15:41:11 rivoplus sudo[15908]: pam_unix(sudo:session): session closed for user root Mar 28 15:41:11 rivoplus sudo[15912]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 15:41:11 rivoplus sudo[15912]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 28 15:41:11 rivoplus sudo[15912]: pam_unix(sudo:session): session closed for user root Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 28 15:41:11 rivoplus volumio[3188]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.11 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: 10 Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 28 15:41:11 rivoplus volumio[3188]: info: Received Get System Info Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 15:41:11 rivoplus volumio[3188]: info: Discovery: Getting this device information Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:41:11 rivoplus volumio[3188]: info: Listing playlists Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 15:41:11 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 28 15:41:12 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 28 15:41:13 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 15:41:13 rivoplus volumio[3188]: info: Received Get System Info Mar 28 15:41:13 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 15:41:13 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 15:41:13 rivoplus volumio[3188]: info: Discovery: Getting this device information Mar 28 15:41:13 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:41:13 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 15:41:14 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:14.116+09:00 level=INFO msg="new address was allocated" component=ble/conn old=126 new=127 Mar 28 15:41:14 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:14 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 15:41:14 rivoplus volumio[3188]: info: Received Get System Info Mar 28 15:41:14 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 15:41:14 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 15:41:14 rivoplus volumio[3188]: info: Discovery: Getting this device information Mar 28 15:41:14 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:41:14 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 15:41:14 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 15:41:17 rivoplus volumio[3188]: No protocol specified Mar 28 15:41:17 rivoplus volumio[3188]: xcb_connection_has_error() returned true Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 28 15:41:17 rivoplus volumio[3188]: No protocol specified Mar 28 15:41:17 rivoplus volumio[3188]: xcb_connection_has_error() returned true Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: raat , getAdditionalUiSection Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: inputs , getAdditionalUiSection Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 15:41:17 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 15:41:18 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:18.796+09:00 level=INFO msg="new address was allocated" component=ble/conn old=127 new=128 Mar 28 15:41:19 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:19 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:21 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 28 15:41:23 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:23.836+09:00 level=INFO msg="new address was allocated" component=ble/conn old=128 new=129 Mar 28 15:41:24 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:24 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:27 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:27.455+09:00 level=INFO msg="new address was allocated" component=ble/conn old=129 new=130 Mar 28 15:41:27 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:28 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:30 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 15:41:30 rivoplus volumio[3188]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 28 15:41:30 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 28 15:41:30 rivoplus volumio[3188]: info: Received Get System Version Mar 28 15:41:30 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 15:41:30 rivoplus volumio[3188]: info: Received Get System Info Mar 28 15:41:30 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 15:41:30 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 15:41:30 rivoplus volumio[3188]: info: Discovery: Getting this device information Mar 28 15:41:30 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:41:30 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 15:41:31 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:31.273+09:00 level=INFO msg="new address was allocated" component=ble/conn old=130 new=131 Mar 28 15:41:31 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:32 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:35.599+09:00 level=INFO msg="new address was allocated" component=ble/conn old=131 new=132 Mar 28 15:41:35 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:36 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:39 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:39.194+09:00 level=INFO msg="new address was allocated" component=ble/conn old=132 new=133 Mar 28 15:41:39 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:39 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:43 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:43.574+09:00 level=INFO msg="new address was allocated" component=ble/conn old=133 new=134 Mar 28 15:41:43 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:44 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:47 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:47.594+09:00 level=INFO msg="new address was allocated" component=ble/conn old=134 new=135 Mar 28 15:41:47 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:48 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:52 rivoplus volumio[3188]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 15:41:52 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 28 15:41:52 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 28 15:41:52 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 28 15:41:52 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Mar 28 15:41:52 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: inputs , getAdditionalUiSection Mar 28 15:41:52 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:52.154+09:00 level=INFO msg="new address was allocated" component=ble/conn old=135 new=136 Mar 28 15:41:52 rivoplus volumio[3188]: info: Received Get System Version Mar 28 15:41:52 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 15:41:52 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:52 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:57 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:41:57.434+09:00 level=INFO msg="new address was allocated" component=ble/conn old=136 new=137 Mar 28 15:41:57 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:58 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:41:58 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 15:41:58 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 28 15:42:01 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:01.873+09:00 level=INFO msg="new address was allocated" component=ble/conn old=137 new=138 Mar 28 15:42:02 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:02 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:06 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:06.254+09:00 level=INFO msg="new address was allocated" component=ble/conn old=138 new=139 Mar 28 15:42:06 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:06 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:10 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:10.153+09:00 level=INFO msg="new address was allocated" component=ble/conn old=139 new=140 Mar 28 15:42:10 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:10 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:15 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:15.313+09:00 level=INFO msg="new address was allocated" component=ble/conn old=140 new=141 Mar 28 15:42:15 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:15 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:16 rivoplus volumio[3188]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/rivoplus/buster/armhf Mar 28 15:42:16 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:16.890+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:18 rivoplus volumio[3188]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/rivoplus/buster/armhf Mar 28 15:42:18 rivoplus volumio[3188]: info: Folder /tmp/plugins removed Mar 28 15:42:18 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:18.857+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:19 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:19.918+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:19 rivoplus volumio[3188]: info: Check plugin dependencies Mar 28 15:42:20 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 15:42:20 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:20.043+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:20 rivoplus volumio[3188]: info: Checking if plugin already exists Mar 28 15:42:20 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:20.049+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:20 rivoplus volumio[3188]: info: Rename folder Mar 28 15:42:20 rivoplus volumio[3188]: info: Folder /tmp/downloaded_plugin.zip removed Mar 28 15:42:20 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:20.100+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:20 rivoplus volumio[3188]: info: Move to category Mar 28 15:42:20 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:20.653+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:20 rivoplus volumio[3188]: info: Checking if install.sh is present Mar 28 15:42:20 rivoplus volumio[3188]: info: Executing install.sh Mar 28 15:42:20 rivoplus sudo[16108]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/music_service/spop/install.sh Mar 28 15:42:20 rivoplus sudo[16108]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 28 15:42:20 rivoplus volumio[3188]: info: Installing Go-librespot Mar 28 15:42:20 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:20.808+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:20 rivoplus volumio[3188]: info: Checking old vollibrespot installs Mar 28 15:42:20 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:20.820+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:20 rivoplus systemd[1]: Reloading. Mar 28 15:42:21 rivoplus systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Mar 28 15:42:21 rivoplus systemd[1]: serial-getty@ttyS0.service: Current command vanished from the unit file, execution of the command list won't be resumed. Mar 28 15:42:22 rivoplus volumio[3188]: info: Downloading daemon Mar 28 15:42:22 rivoplus systemd[1]: Starting Daily apt download activities... Mar 28 15:42:22 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:22.110+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:22 rivoplus volumio[3188]: ------------------------------------ BT MESSAGE: BT STATUS: running Mar 28 15:42:22 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:22.333+09:00 level=INFO msg="new address was allocated" component=ble/conn old=141 new=142 Mar 28 15:42:22 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:22 rivoplus systemd[1]: apt-daily.service: Succeeded. Mar 28 15:42:22 rivoplus systemd[1]: Started Daily apt download activities. Mar 28 15:42:23 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:24 rivoplus volumio[3188]: info: Creating directories Mar 28 15:42:24 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:24.982+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:24 rivoplus volumio[3188]: info: Creating data directory Mar 28 15:42:24 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:24.987+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:25 rivoplus volumio[3188]: info: Creating Start Script Mar 28 15:42:25 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:25.007+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:25 rivoplus systemd[1]: Reloading. Mar 28 15:42:25 rivoplus systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Mar 28 15:42:26 rivoplus sudo[16108]: pam_unix(sudo:session): session closed for user root Mar 28 15:42:26 rivoplus volumio[3188]: Plugin install end detected on script Mar 28 15:42:26 rivoplus volumio[3188]: info: Install script completed Mar 28 15:42:26 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:26.170+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:26 rivoplus volumio[3188]: info: Adding reference to registry Mar 28 15:42:26 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:26.180+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 15:42:26 rivoplus volumio[3188]: info: Done installing plugin. Mar 28 15:42:26 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 15:42:26 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 28 15:42:26 rivoplus volumio[3188]: info: Folder /tmp/plugins removed Mar 28 15:42:26 rivoplus volumio[3188]: info: Folder /tmp/downloaded_plugin.zip removed Mar 28 15:42:26 rivoplus volumio[3188]: info: Folder /data/temp removed Mar 28 15:42:26 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:26.414+09:00 level=INFO msg="new address was allocated" component=ble/conn old=142 new=143 Mar 28 15:42:26 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:27 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:27 rivoplus volumio[3188]: info: Enabling plugin spop Mar 28 15:42:27 rivoplus volumio[3188]: info: Loading plugin "spop"... Mar 28 15:42:29 rivoplus volumio[3188]: info: PLUGIN START: spop Mar 28 15:42:29 rivoplus volumio[3188]: info: Creating Spotify config file Mar 28 15:42:29 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 15:42:29 rivoplus volumio[3188]: info: Done. Mar 28 15:42:29 rivoplus volumio[3188]: info: Spotify config file written Mar 28 15:42:29 rivoplus volumio[3188]: info: No need to fix Spotify hosts Mar 28 15:42:29 rivoplus sudo[16233]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 15:42:29 rivoplus sudo[16233]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 28 15:42:29 rivoplus systemd[1]: Started go-librespot Daemon. Mar 28 15:42:29 rivoplus sudo[16233]: pam_unix(sudo:session): session closed for user root Mar 28 15:42:29 rivoplus go-librespot[16235]: go-librespot daemon starting... Mar 28 15:42:29 rivoplus go-librespot[16235]: time="2026-03-28T15:42:29+09:00" level=info msg="running go-librespot 0.7.1" Mar 28 15:42:29 rivoplus go-librespot[16235]: time="2026-03-28T15:42:29+09:00" level=debug msg="no app state found" Mar 28 15:42:29 rivoplus go-librespot[16235]: time="2026-03-28T15:42:29+09:00" level=debug msg="stored credentials not found" Mar 28 15:42:29 rivoplus go-librespot[16235]: time="2026-03-28T15:42:29+09:00" level=info msg="generated new device id: edb2691014753b386f2b8be252a09490be9d5f48" Mar 28 15:42:29 rivoplus go-librespot[16235]: time="2026-03-28T15:42:29+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 15:42:29 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:29.834+09:00 level=INFO msg="new address was allocated" component=ble/conn old=143 new=144 Mar 28 15:42:29 rivoplus go-librespot[16235]: time="2026-03-28T15:42:29+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 28 15:42:29 rivoplus go-librespot[16235]: time="2026-03-28T15:42:29+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 28 15:42:29 rivoplus go-librespot[16235]: time="2026-03-28T15:42:29+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 28 15:42:29 rivoplus go-librespot[16235]: time="2026-03-28T15:42:29+09:00" level=info msg="zeroconf server listening on port 39651" Mar 28 15:42:29 rivoplus go-librespot[16235]: time="2026-03-28T15:42:29+09:00" level=info msg="using avahi-daemon avahi 0.7 for mDNS service registration" Mar 28 15:42:30 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:30 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:32 rivoplus volumio[3188]: info: go-librespot daemon successfully initialized Mar 28 15:42:34 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:34.454+09:00 level=INFO msg="new address was allocated" component=ble/conn old=144 new=145 Mar 28 15:42:34 rivoplus dbus-daemon[2840]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.18" (uid=0 pid=3796 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3326 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 28 15:42:34 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:34.875+09:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="00:00:00:00:00:00%90 @ 0x1401860" latency=1m26.1647125s timeout=10s Mar 28 15:42:34 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:34.875+09:00 level=INFO msg="emitting device capabilities changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.002+09:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="00:00:00:00:00:00%90 @ 0x1401860" latency=1m24.561705261s timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Mar 28 15:42:35 rivoplus volumio[3188]: info: Received Get System Info Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 15:42:35 rivoplus volumio[3188]: info: Discovery: Getting this device information Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.121+09:00 level=INFO msg="emitting device name changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" name=Rivoplus Mar 28 15:42:35 rivoplus volumio[3188]: info: Initializing connection to go-librespot Websocket Mar 28 15:42:35 rivoplus go-librespot[16235]: time="2026-03-28T15:42:35+09:00" level=debug msg="new websocket client" Mar 28 15:42:35 rivoplus volumio[3188]: info: Connection to go-librespot Websocket established Mar 28 15:42:35 rivoplus go-librespot[16235]: time="2026-03-28T15:42:35+09:00" level=debug msg="obtained new client token: AADDvld4BfKhHYBBDe0WAqZ8cDNHpRPW3pNhTGezoYu0e8dYqueLVGf0KF+phoUieGADz5MsS1dezFO1/pTg9hoX+apsZ7FcZL4MFuYichlniH3dclQwiOpaWzFt6nxtbyWS5deBFi8NyajEvlLiShryZnxp8wQD9x9x5ZDGK/SH9OVZduD4qRQEMOi06H67FBr7ZdSncMKov4ebPceKwvdwoeBdKmRf9rXmC04WYyvhl7JK5+mx4kW2Hg==" Mar 28 15:42:35 rivoplus go-librespot[16235]: time="2026-03-28T15:42:35+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.656+09:00 level=INFO msg="emitting device language changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" language=ja Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.659+09:00 level=INFO msg="emitting device timezone changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" timezone=Asia/Tokyo Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.665+09:00 level=INFO msg="emitting ethernet info changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" available=true connected=true macAddress=02:00:00:28:13:01 ip4Address=192.168.0.4/24 ip6Address= Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.669+09:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.669+09:00 level=INFO msg="emitting device setup status changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" setupComplete=true Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Mar 28 15:42:35 rivoplus go-librespot[16235]: time="2026-03-28T15:42:35+09:00" level=debug msg="completed keyexchange" Mar 28 15:42:35 rivoplus go-librespot[16235]: time="2026-03-28T15:42:35+09:00" level=debug msg="completed challenge" Mar 28 15:42:35 rivoplus volumio[3188]: No protocol specified Mar 28 15:42:35 rivoplus volumio[3188]: xcb_connection_has_error() returned true Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 28 15:42:35 rivoplus volumio[3188]: amixer -c 5 info | grep "Comtrue-inc UAC2 Device" Mar 28 15:42:35 rivoplus go-librespot[16235]: time="2026-03-28T15:42:35+09:00" level=info msg="authenticated AP" username="or*******84" Mar 28 15:42:35 rivoplus volumio[3188]: No protocol specified Mar 28 15:42:35 rivoplus volumio[3188]: xcb_connection_has_error() returned true Mar 28 15:42:35 rivoplus volumio[3188]: Card hw:5 'Device'/'Comtrue-inc Comtrue-inc UAC2 Device at usb-xhci-hcd.0.auto-1.4.3, high speed' Mar 28 15:42:35 rivoplus volumio[3188]: amixer -c 5 info | grep "Comtrue-inc UAC2 Device" Mar 28 15:42:35 rivoplus go-librespot[16235]: time="2026-03-28T15:42:35+09:00" level=info msg="authenticated Login5" username="or*******84" Mar 28 15:42:35 rivoplus go-librespot[16235]: time="2026-03-28T15:42:35+09:00" level=info msg="accepted zeroconf from iPhone" username="or*******84" Mar 28 15:42:35 rivoplus volumio[3188]: No protocol specified Mar 28 15:42:35 rivoplus volumio[3188]: xcb_connection_has_error() returned true Mar 28 15:42:35 rivoplus volumio[3188]: Card hw:5 'Device'/'Comtrue-inc Comtrue-inc UAC2 Device at usb-xhci-hcd.0.auto-1.4.3, high speed' Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.924+09:00 level=INFO msg="emitting audio outputs changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" selectedOutputId=5 Mar 28 15:42:35 rivoplus volumio[3188]: info: Received Get System Info Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 15:42:35 rivoplus volumio[3188]: info: Discovery: Getting this device information Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.952+09:00 level=INFO msg="emitting software info changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" currentVersion=3.912 latestVersion=3.912 Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.952+09:00 level=INFO msg="emitting software update progress event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" status=UPDATE_STATUS_NONE progress=0 Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.952+09:00 level=INFO msg="emitting user changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" userId= Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.953+09:00 level=INFO msg="emitting music providers changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" providers=3 Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.953+09:00 level=INFO msg="emitting plugins changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" plugins=26 Mar 28 15:42:35 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.957+09:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" state=STATUS_PLAYING positionMs=93572000 volume=100 Mar 28 15:42:35 rivoplus volumio5-onboarding[3796]: time=2026-03-28T15:42:35.958+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%90 @ 0x1401860" id= title= Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="dealer connection opened" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=trace msg="starting accesspoint recv loop" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=trace msg="starting dealer recv loop" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=trace msg="received accesspoint ping" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="received connection id: ZWVkNzVkMzYtYjdj...N0E4NTcyMUY5Rg==" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=trace msg="received accesspoint pong ack" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="put connect state because NEW_DEVICE" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="update volume requested to 65535/65535" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="handling transfer player command from c08ce49bb079ebc31debea51afa61a3b42d65c6c" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="resolved context of track" uri="spotify:album:0ZjFSIHLglwavZUgcCboJW" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=trace msg="fetched new page 0 with 26 items (list: 26)" uri="spotify:album:0ZjFSIHLglwavZUgcCboJW" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="loading track (paused: true, position: 6985ms)" uri="spotify:track:4WZdUTYAUwMG63GCNA5jtk" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=trace msg="emitting websocket event: will_play" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2021" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="selected format OGG_VORBIS_320 (7d2f0d4bb2a6ae72b9f7e81eaa0217ff47bb8297)" uri="spotify:track:4WZdUTYAUwMG63GCNA5jtk" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="requested aes key for file 7d2f0d4bb2a6ae72b9f7e81eaa0217ff47bb8297, gid: 4WZdUTYAUwMG63GCNA5jtk" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4WZdUTYAUwMG63GCNA5jtk" Mar 28 15:42:36 rivoplus go-librespot[16235]: time="2026-03-28T15:42:36+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1464" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="fetched first chunk of 25, total size is 12960228 bytes" uri="spotify:track:4WZdUTYAUwMG63GCNA5jtk" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=trace msg="seek to 6985ms (diff: 133ms, samples: 308038, bytes: 271546)" uri="spotify:track:4WZdUTYAUwMG63GCNA5jtk" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="created new output device" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=info msg="loaded track \"traveling - Re-Recording\" (paused: true, position: 6985ms, duration: 308695ms, prefetched: false)" uri="spotify:track:4WZdUTYAUwMG63GCNA5jtk" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="fetched chunk 2/24, size: 524288" uri="spotify:track:4WZdUTYAUwMG63GCNA5jtk" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=trace msg="emitting websocket event: metadata" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=trace msg="emitting websocket event: active" Mar 28 15:42:37 rivoplus volumio[3188]: info: Aligning Spotify Volume to Volumio Volume Mar 28 15:42:37 rivoplus volumio[3188]: info: CoreCommandRouter::volumioGetState Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="sending successful reply for dealer request" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="fetched chunk 3/24, size: 524288" uri="spotify:track:4WZdUTYAUwMG63GCNA5jtk" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="fetched chunk 1/24, size: 524288" uri="spotify:track:4WZdUTYAUwMG63GCNA5jtk" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=trace msg="emitting websocket event: paused" Mar 28 15:42:37 rivoplus volumio[3188]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 28 15:42:37 rivoplus volumio[3188]: TypeError: Cannot read property 'service' of undefined Mar 28 15:42:37 rivoplus volumio[3188]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:345:50) Mar 28 15:42:37 rivoplus volumio[3188]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:279:18) Mar 28 15:42:37 rivoplus volumio[3188]: at WebSocket.message (/data/plugins/music_service/spop/index.js:198:14) Mar 28 15:42:37 rivoplus volumio[3188]: at WebSocket.emit (events.js:400:28) Mar 28 15:42:37 rivoplus volumio[3188]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1225:20) Mar 28 15:42:37 rivoplus volumio[3188]: at Receiver.emit (events.js:400:28) Mar 28 15:42:37 rivoplus volumio[3188]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 28 15:42:37 rivoplus volumio[3188]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 28 15:42:37 rivoplus volumio[3188]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 28 15:42:37 rivoplus volumio[3188]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 28 15:42:37 rivoplus volumio[3188]: at writeOrBuffer (internal/streams/writable.js:358:12) Mar 28 15:42:37 rivoplus volumio[3188]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Mar 28 15:42:37 rivoplus volumio[3188]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1360:35) Mar 28 15:42:37 rivoplus volumio[3188]: at Socket.emit (events.js:400:28) Mar 28 15:42:37 rivoplus volumio[3188]: at addChunk (internal/streams/readable.js:293:12) Mar 28 15:42:37 rivoplus volumio[3188]: at readableAddChunk (internal/streams/readable.js:267:9) Mar 28 15:42:37 rivoplus volumio[3188]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 15:42:37 rivoplus go-librespot[16235]: time="2026-03-28T15:42:37+09:00" level=trace msg="emitting websocket event: volume" Mar 28 15:42:38 rivoplus sudo[16262]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-03-28 15:41 Mar 28 15:42:38 rivoplus sudo[16262]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 11:19:27 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo Plus" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo Plus" VOLUMIO_HASH="a7285124ffc88c43265bb2db03526f6a"