May 27 20:50:11 rv systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 11202. May 27 20:50:11 rv systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. May 27 20:50:11 rv systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. May 27 20:50:11 rv upmpdcli[6157]: Could not open config: /tmp/upmpdcli.conf May 27 20:50:11 rv systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE May 27 20:50:11 rv systemd[1]: upmpdcli.service: Failed with result 'exit-code'. May 27 20:50:12 rv volumio[1147]: info: CoreCommandRouter::volumioGetState May 27 20:50:12 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:50:12 rv kernel: May 27 20:50:12 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:50:12 rv kernel: May 27 20:50:12 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:50:16 rv go-librespot[1561]: time="2026-05-27T20:50:16+02:00" level=trace msg="sent dealer ping" May 27 20:50:16 rv go-librespot[1561]: time="2026-05-27T20:50:16+02:00" level=trace msg="received dealer pong" May 27 20:50:25 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_D8_15_52_E2_C5_CC, ...) May 27 20:50:25 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_ED_9D_92_C5_9C_7E, ...) May 27 20:50:26 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_75_44_B2_EF_54_B8, ...) May 27 20:50:26 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_D6_4D_75_6A_2C_A9, ...) May 27 20:50:26 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_7F_C9_9A_33_A5_10, ...) May 27 20:50:26 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_53_4A_52_FE_01_B9, ...) May 27 20:50:26 rv bluealsa[973]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_D6_4D_75_6A_2C_A9, ...) May 27 20:50:26 rv systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 11203. May 27 20:50:26 rv systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. May 27 20:50:26 rv systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. May 27 20:50:26 rv upmpdcli[6189]: Could not open config: /tmp/upmpdcli.conf May 27 20:50:26 rv systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE May 27 20:50:26 rv systemd[1]: upmpdcli.service: Failed with result 'exit-code'. May 27 20:50:28 rv volumio[1147]: info: CoreCommandRouter::volumioGetState May 27 20:50:28 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:50:28 rv kernel: May 27 20:50:28 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:50:28 rv kernel: May 27 20:50:28 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:50:41 rv systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 11204. May 27 20:50:41 rv systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. May 27 20:50:41 rv systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. May 27 20:50:41 rv upmpdcli[6207]: Could not open config: /tmp/upmpdcli.conf May 27 20:50:41 rv systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE May 27 20:50:41 rv systemd[1]: upmpdcli.service: Failed with result 'exit-code'. May 27 20:50:43 rv volumio[1147]: info: CoreCommandRouter::volumioGetState May 27 20:50:43 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:50:43 rv kernel: May 27 20:50:43 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:50:43 rv kernel: May 27 20:50:43 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:50:46 rv go-librespot[1561]: time="2026-05-27T20:50:46+02:00" level=trace msg="sent dealer ping" May 27 20:50:46 rv go-librespot[1561]: time="2026-05-27T20:50:46+02:00" level=trace msg="received dealer pong" May 27 20:50:55 rv bluealsa[973]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_75_44_B2_EF_54_B8, ...) May 27 20:50:55 rv bluealsa[973]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7F_C9_9A_33_A5_10, ...) May 27 20:50:55 rv bluealsa[973]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_D8_15_52_E2_C5_CC, ...) May 27 20:50:56 rv go-librespot[1561]: time="2026-05-27T20:50:56+02:00" level=debug msg="skipping dealer message" uri="hm://collection/collection/31vfux6f34ey7gen45wcgenlbwgm" May 27 20:50:56 rv go-librespot[1561]: time="2026-05-27T20:50:56+02:00" level=debug msg="skipping dealer message" uri="hm://collection/collection/31vfux6f34ey7gen45wcgenlbwgm/json" May 27 20:50:56 rv go-librespot[1561]: time="2026-05-27T20:50:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 258" May 27 20:50:56 rv go-librespot[1561]: time="2026-05-27T20:50:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 338" May 27 20:50:56 rv systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 11205. May 27 20:50:56 rv systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. May 27 20:50:56 rv bluealsa[973]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_ED_9D_92_C5_9C_7E, ...) May 27 20:50:56 rv bluealsa[973]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_53_4A_52_FE_01_B9, ...) May 27 20:50:56 rv systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. May 27 20:50:56 rv upmpdcli[6240]: Could not open config: /tmp/upmpdcli.conf May 27 20:50:56 rv systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE May 27 20:50:56 rv systemd[1]: upmpdcli.service: Failed with result 'exit-code'. May 27 20:50:58 rv volumio[1147]: info: CoreCommandRouter::volumioGetState May 27 20:50:58 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:50:58 rv kernel: May 27 20:50:58 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:50:58 rv kernel: May 27 20:50:58 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:51:01 rv python[1149]: 2026-05-27 20:51:01 [INFO] GET / 200 3ms May 27 20:51:01 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_ED_9D_92_C5_9C_7E, ...) May 27 20:51:01 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5E_64_1E_C5_6C_DB, ...) May 27 20:51:01 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_59_0D_BE_B2_7E_A3, ...) May 27 20:51:01 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_D6_4D_75_6A_2C_A9, ...) May 27 20:51:01 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_53_4A_52_FE_01_B9, ...) May 27 20:51:01 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_D8_15_52_E2_C5_CC, ...) May 27 20:51:01 rv bluealsa[973]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_ED_9D_92_C5_9C_7E, ...) May 27 20:51:01 rv volumio[1147]: info: CoreCommandRouter::volumioGetState May 27 20:51:01 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:01 rv python[1149]: 2026-05-27 20:51:01 [INFO] GET /status 200 216ms May 27 20:51:02 rv python[1149]: 2026-05-27 20:51:02 [INFO] GET /metrics 200 3ms May 27 20:51:05 rv python[1149]: 2026-05-27 20:51:05 [INFO] GET /camera/snapshot/2 200 4078ms May 27 20:51:05 rv python[1149]: 2026-05-27 20:51:05 [INFO] GET /camera/snapshot/1 200 4064ms May 27 20:51:06 rv volumio[1147]: info: CoreCommandRouter::volumioGetState May 27 20:51:06 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:06 rv python[1149]: 2026-05-27 20:51:06 [INFO] GET /status 200 17ms May 27 20:51:06 rv python[1149]: 2026-05-27 20:51:06 [INFO] GET /metrics 200 3ms May 27 20:51:08 rv python[1149]: 2026-05-27 20:51:08 [INFO] radio: tune station=357 May 27 20:51:08 rv python[1149]: 2026-05-27 20:51:08 [INFO] Playback start: USB hub port off, powering on May 27 20:51:08 rv kernel: May 27 20:51:08 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:51:08 rv kernel: May 27 20:51:08 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:51:08 rv python[1149]: 2026-05-27 20:51:08 [INFO] USB hub port 3 powered on May 27 20:51:08 rv kernel: May 27 20:51:08 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:51:08 rv kernel: May 27 20:51:08 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:51:09 rv kernel: usb 1-1.1.3: new high-speed USB device number 15 using dwc_otg May 27 20:51:09 rv kernel: usb 1-1.1.3: New USB device found, idVendor=152a, idProduct=8750, bcdDevice= 1.39 May 27 20:51:09 rv kernel: usb 1-1.1.3: New USB device strings: Mfr=1, Product=3, SerialNumber=0 May 27 20:51:09 rv kernel: usb 1-1.1.3: Product: D50 III May 27 20:51:09 rv kernel: usb 1-1.1.3: Manufacturer: Topping May 27 20:51:09 rv kernel: input: Topping D50 III as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1/1-1.1.3/1-1.1.3:1.3/0003:152A:8750.000A/input/input12 May 27 20:51:09 rv kernel: hid-generic 0003:152A:8750.000A: input,hidraw0: USB HID v1.10 Device [Topping D50 III] on usb-3f980000.usb-1.1.3/input3 May 27 20:51:09 rv volumio[1147]: info: May 27 20:51:09 rv volumio[1147]: ---------------------------- USB Audio Device Attached May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::Close All Modals sent May 27 20:51:09 rv volumio[1147]: info: Preparing to save Alsa Options, stopping services first May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::volumioGetState May 27 20:51:09 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::volumioPause May 27 20:51:09 rv volumio[1147]: info: CoreStateMachine::pause May 27 20:51:09 rv volumio[1147]: info: Saving Audio Output to: {"disallowPush":true,"output_device":{"value":"5","label":"D50 III","alsacard":"III"},"i2s":false} May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 20:51:09 rv volumio[1147]: info: Setting mixer D50 III for card D50 III May 27 20:51:09 rv vtcs[22376]: [2026-05-27 20:51:09.686] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE May 27 20:51:09 rv vtcs[22376]: [2026-05-27 20:51:09.687] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected May 27 20:51:09 rv sudo[6320]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 20:51:09 rv sudo[6320]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::volumioUpdateVolumeSettings May 27 20:51:09 rv volumio[1147]: info: Updating Volume Controller Parameters: Device: 5 Name: D50 III Mixer: D50 III Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 27 20:51:09 rv volumio[1147]: info: Disabling external Volume Control May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::getUIConfigOnPlugin May 27 20:51:09 rv volumio[1147]: info: Preparing to generate the ALSA configuration file May 27 20:51:09 rv systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... May 27 20:51:09 rv systemd[1]: vtcs.service: Killing process 22388 (vtcs) with signal SIGKILL. May 27 20:51:09 rv systemd[1]: vtcs.service: Deactivated successfully. May 27 20:51:09 rv systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. May 27 20:51:09 rv systemd[1]: vtcs.service: Consumed 3.947s CPU time. May 27 20:51:09 rv sudo[6320]: pam_unix(sudo:session): session closed for user root May 27 20:51:09 rv sudo[6327]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 20:51:09 rv sudo[6327]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 20:51:09 rv sudo[6327]: pam_unix(sudo:session): session closed for user root May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 27 20:51:09 rv volumio[1147]: info: Asound.conf file unchanged, so no further update is needed May 27 20:51:09 rv volumio[1147]: info: Output device has changed, restarting MPD May 27 20:51:09 rv volumio[1147]: info: Output device has changed, restarting Shairport Sync May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 20:51:09 rv sudo[6339]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 27 20:51:09 rv sudo[6339]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 20:51:09 rv sudo[6339]: pam_unix(sudo:session): session closed for user root May 27 20:51:09 rv sudo[6343]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 27 20:51:09 rv sudo[6343]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 20:51:09 rv volumio[1147]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 27 20:51:09 rv volumio[1147]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration May 27 20:51:09 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:10 rv sudo[6351]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 20:51:10 rv sudo[6351]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 20:51:10 rv systemd[1]: Stopping mpd.service - Music Player Daemon... May 27 20:51:10 rv volumio[1147]: info: MPD Permissions set May 27 20:51:10 rv volumio[1147]: info: VolumeController:: Volume=100 Mute =false May 27 20:51:10 rv volumio[1147]: info: CoreStateMachine::pushState May 27 20:51:10 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::volumioPushState May 27 20:51:10 rv volumio[1147]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:10 rv sudo[6353]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 20:51:10 rv sudo[6353]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 20:51:10 rv systemd[1]: mpd.service: Deactivated successfully. May 27 20:51:10 rv systemd[1]: Stopped mpd.service - Music Player Daemon. May 27 20:51:10 rv systemd[1]: mpd.service: Consumed 37.499s CPU time. May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 20:51:10 rv volumio[1147]: info: Starting Shairport Sync May 27 20:51:10 rv systemd[1]: mpd.socket: Deactivated successfully. May 27 20:51:10 rv systemd[1]: Closed mpd.socket - Music Player Daemon Socket. May 27 20:51:10 rv systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... May 27 20:51:10 rv sudo[6362]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 27 20:51:10 rv sudo[6362]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 20:51:10 rv systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. May 27 20:51:10 rv systemd[1]: Starting mpd.service - Music Player Daemon... May 27 20:51:10 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: raat , restartRaat May 27 20:51:10 rv sudo[6351]: pam_unix(sudo:session): session closed for user root May 27 20:51:10 rv systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... May 27 20:51:10 rv systemd[1]: shairport-sync.service: Deactivated successfully. May 27 20:51:10 rv systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 27 20:51:10 rv systemd[1]: shairport-sync.service: Consumed 36.125s CPU time. May 27 20:51:10 rv sudo[6353]: pam_unix(sudo:session): session closed for user root May 27 20:51:10 rv systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 27 20:51:10 rv sudo[6362]: pam_unix(sudo:session): session closed for user root May 27 20:51:10 rv volumio[1147]: info: Shairport-Sync Started May 27 20:51:10 rv sudo[6366]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 27 20:51:10 rv sudo[6366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 27 20:51:10 rv sudo[6366]: pam_unix(sudo:session): session closed for user root May 27 20:51:11 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_ED_9D_92_C5_9C_7E, ...) May 27 20:51:11 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_7F_C9_9A_33_A5_10, ...) May 27 20:51:11 rv bluealsa[973]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_75_44_B2_EF_54_B8, ...) May 27 20:51:11 rv bluealsa[973]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_D8_15_52_E2_C5_CC, ...) May 27 20:51:11 rv bluealsa[973]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_D6_4D_75_6A_2C_A9, ...) May 27 20:51:11 rv volumio[1147]: info: CoreCommandRouter::volumioGetState May 27 20:51:11 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:11 rv python[1149]: 2026-05-27 20:51:11 [INFO] GET /status 200 311ms May 27 20:51:12 rv python[1149]: 2026-05-27 20:51:12 [INFO] GET /metrics 200 5ms May 27 20:51:12 rv systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 11206. May 27 20:51:12 rv systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. May 27 20:51:12 rv systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. May 27 20:51:12 rv upmpdcli[6388]: Could not open config: /tmp/upmpdcli.conf May 27 20:51:12 rv systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE May 27 20:51:12 rv systemd[1]: upmpdcli.service: Failed with result 'exit-code'. May 27 20:51:12 rv volumio[1147]: info: TidalConnect service stoped! May 27 20:51:12 rv volumio[1147]: info: TidalConnect service stoped! May 27 20:51:12 rv volumio[1147]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 27 20:51:12 rv volumio[1147]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 27 20:51:12 rv sudo[6399]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 27 20:51:12 rv sudo[6399]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 20:51:13 rv systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. May 27 20:51:13 rv sudo[6399]: pam_unix(sudo:session): session closed for user root May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::volumioGetState May 27 20:51:13 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:13 rv python[1149]: 2026-05-27 20:51:13 [INFO] USB watcher: Volumio=stop port=on grace=True May 27 20:51:13 rv kernel: May 27 20:51:13 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:51:13 rv kernel: May 27 20:51:13 rv kernel: WARN::dwc_otg_hcd_hub_control:3805: DWC OTG HCD - Unknown hub control request type or invalid typeReq: 8006h wIndex: 0h wValue: f00h May 27 20:51:13 rv volumio[1147]: info: TidalConnect service stoped! May 27 20:51:13 rv volumio[1147]: info: Executing endpoint tc_getconfig May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig May 27 20:51:13 rv vtcs[6402]: STARTING TidalConnect services, version: 1.6.1 May 27 20:51:13 rv vtcs[6402]: STARTED TidalConnect services. May 27 20:51:13 rv volumio[1147]: info: TidalConnect service stoped! May 27 20:51:13 rv volumio[1147]: info: Executing endpoint tc_connect May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect May 27 20:51:13 rv volumio[1147]: info: Connecting to TidalConnect May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::servicePushState May 27 20:51:13 rv volumio[1147]: info: CoreStateMachine::pushState May 27 20:51:13 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::volumioPushState May 27 20:51:13 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:13 rv volumio[1147]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} May 27 20:51:13 rv volumio[1147]: verbose: CURRENT POSITION 0 May 27 20:51:13 rv volumio[1147]: info: CoreStateMachine::syncState stateService stop May 27 20:51:13 rv volumio[1147]: info: CoreStateMachine::syncState currentStatus stop May 27 20:51:13 rv volumio[1147]: info: CoreStateMachine::pushState May 27 20:51:13 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::volumioPushState May 27 20:51:13 rv volumio[1147]: info: No code May 27 20:51:13 rv volumio[1147]: info: CoreStateMachine::pushState May 27 20:51:13 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::volumioPushState May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::servicePushState May 27 20:51:13 rv volumio[1147]: info: CoreStateMachine::pushState May 27 20:51:13 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::volumioPushState May 27 20:51:13 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:13 rv volumio[1147]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} May 27 20:51:13 rv volumio[1147]: verbose: CURRENT POSITION 0 May 27 20:51:13 rv volumio[1147]: info: CoreStateMachine::syncState stateService stop May 27 20:51:13 rv volumio[1147]: info: CoreStateMachine::syncState currentStatus stop May 27 20:51:13 rv volumio[1147]: info: CoreStateMachine::pushState May 27 20:51:13 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::volumioPushState May 27 20:51:13 rv volumio[1147]: info: No code May 27 20:51:13 rv volumio[1147]: info: CoreStateMachine::pushState May 27 20:51:13 rv volumio[1147]: info: CorePlayQueue::getTrack 0 May 27 20:51:13 rv volumio[1147]: info: CoreCommandRouter::volumioPushState May 27 20:51:13 rv mpd[6384]: 2026-05-27T20:51:13 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 27 20:51:13 rv systemd[1]: Started mpd.service - Music Player Daemon. May 27 20:51:13 rv volumio[1147]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 27 20:51:13 rv volumio[1147]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 27 20:51:13 rv volumio[1147]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 27 20:51:13 rv volumio[1147]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 27 20:51:13 rv sudo[6343]: pam_unix(sudo:session): session closed for user root May 27 20:51:13 rv volumio[1147]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 27 20:51:13 rv volumio[1147]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 27 20:51:13 rv volumio[1147]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 27 20:51:13 rv volumio[1147]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 27 20:51:13 rv volumio[1147]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 27 20:51:13 rv volumio[1147]: Error: ENOENT: no such file or directory, unlink '/tmp/1uts37DfwHK8b2D9sODYoqWOLoeOLnTvhouZLajd2eGsWfSbT8hlqJAknCEQV99mq9WkHNuY7VAlAQAjyVL1L3p1w0ObSk3chDJ8' May 27 20:51:13 rv volumio[1147]: at Object.unlinkSync (node:fs:1899:3) May 27 20:51:13 rv volumio[1147]: at ControllerTidalconnect.deleteCertificate (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:11265) May 27 20:51:13 rv volumio[1147]: at TidalConnectClient. (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:2774) May 27 20:51:13 rv volumio[1147]: at TidalConnectClient.emit (node:events:514:28) May 27 20:51:13 rv volumio[1147]: at TidalConnectClient.parseData (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:44713) May 27 20:51:13 rv volumio[1147]: at /myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:41683 May 27 20:51:13 rv volumio[1147]: at Array.forEach () May 27 20:51:13 rv volumio[1147]: at Socket. (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:41561) May 27 20:51:13 rv volumio[1147]: at Socket.emit (node:events:514:28) May 27 20:51:13 rv volumio[1147]: at addChunk (node:internal/streams/readable:343:12) { May 27 20:51:13 rv volumio[1147]: errno: -2, May 27 20:51:13 rv volumio[1147]: syscall: 'unlink', May 27 20:51:13 rv volumio[1147]: code: 'ENOENT', May 27 20:51:13 rv volumio[1147]: path: '/tmp/1uts37DfwHK8b2D9sODYoqWOLoeOLnTvhouZLajd2eGsWfSbT8hlqJAknCEQV99mq9WkHNuY7VAlAQAjyVL1L3p1w0ObSk3chDJ8' May 27 20:51:13 rv volumio[1147]: } May 27 20:51:13 rv volumio[1147]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 27 20:51:14 rv sudo[6458]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-27 20:50' May 27 20:51:14 rv sudo[6458]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"