Created attachment 1670986 [details] Libvirtd log of step2 Description of problem: As subject Version-Release number of selected component (if applicable): libvirt-6.0.0-10.virtcov.el8.x86_64, v6.1.0-175-gac36a82464 qemu-kvm-4.2.0-15.module+el8.2.0+6029+618ef2ec.x86_64 How reproducible: 100% Steps to Reproduce: 1. Start an VM with cdrom disk: # virsh dumpxml q35 --inactive|xmllint --xpath //disk - <disk type="file" device="cdrom"> <driver name="qemu" type="raw"/> <source file="/var/lib/libvirt/images/boot1.iso" startupPolicy="optional"/> <backingStore/> <target dev="sdb" bus="scsi"/> <readonly/> <address type="drive" controller="0" bus="0" target="0" unit="1"/> </disk><disk type="file" device="disk"> <driver name="qemu" type="qcow2"/> <source file="/var/lib/libvirt/images/q35.qcow2"/> <target dev="vda" bus="virtio"/> <address type="pci" domain="0x0000" bus="0x02" slot="0x00" function="0x0"/> </disk> 2. Eject cdrom # virsh change-media q35 sdb --eject Successfully ejected media. Actual results: Logs of step2: 2020-03-18 01:41:19.831+0000: 643207: debug : qemuMonitorDelObject:2971 : objalias=pr-helper0 2020-03-18 01:41:19.831+0000: 643207: info : qemuMonitorSend:934 : QEMU_MONITOR_SEND_MSG: mon=0x7f053c0d7500 msg={"execute":"object-del","arguments":{"id":"pr-helper0"},"id":"libvirt-18"} 2020-03-18 01:41:19.831+0000: 643888: info : qemuMonitorIOWrite:430 : QEMU_MONITOR_IO_WRITE: mon=0x7f053c0d7500 buf={"execute":"object-del","arguments":{"id":"pr-helper0"},"id":"libvirt-18"} 2020-03-18 01:41:19.832+0000: 643888: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"id": "libvirt-18", "error": {"class": "GenericError", "desc": "object 'pr-helper0' not found"}}] 2020-03-18 01:41:19.832+0000: 643888: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7f053c0d7500 reply={"id": "libvirt-18", "error": {"class": "GenericError", "desc": "object 'pr-helper0' not found"}} 2020-03-18 01:41:19.832+0000: 643207: debug : qemuMonitorJSONCheckError:401 : unable to execute QEMU command {"execute":"object-del","arguments":{"id":"pr-helper0"},"id":"libvirt-18"}: {"id":"libvirt-18","error":{"class":"GenericError","desc":"object 'pr-helper0' not found"}} 2020-03-18 01:41:19.832+0000: 643207: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'object-del': object 'pr-helper0' not found Expected results: No such error Additional info: Since pr-helper is only used in block device for scsi pr, the error should not appears at file backend
Are there any pre-requisite steps? I failed to reproduce this both upstream and downstream when just starting the VM and trying to eject the media.
Created attachment 1671016 [details] domain xml, libvirtd conf, qemu conf No, I think no necessary previous steps there. And no domain use pr-helper: for i in $(virsh list --name --all);do virsh dumpxml $i|grep reserve;done You can check the domain xml and libvirt conf files in attachment. I reproduce the bug by these configrations on v6.1.0-175-gac36a82464
Oh, I see now. The media changing code always tries to remove the pr daemon even if the backing chain didn't have it.
Fixed upstream: commit 02797541283c2c57620606b083db21b38c69c5c1 Author: Peter Krempa <pkrempa> Date: Wed Mar 18 11:44:01 2020 +0100 qemuDomainChangeEjectableMedia: Don't always remove managed PR daemon When changing media we'd attempt to remove the managed pr daemon even if neither of the images involved in the media change used it. This caused libvirtd to log a spurious error: 2020-03-18 01:41:19.832+0000: 643207: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'object-del': object 'pr-helper0' not found With this patch we completely avoid calling the deletion code.
Verified at : libvirt-6.5.0-1.module+el8.3.0+7323+d54bb644.x86_64 Steps: 1.Start a guest with cdrom type disk: # virsh dumpxml avocado-vt-vm1 |xmllint --xpath //disk - <disk type="file" device="disk" snapshot="no"> <driver name="qemu" type="qcow2"/> <source file="/var/lib/libvirt/images/RHEL-8.3-x86_64-latest.qcow2" index="2"/> <backingStore/> <target dev="vda" bus="virtio"/> <alias name="virtio-disk0"/> <address type="pci" domain="0x0000" bus="0x00" slot="0x0d" function="0x0"/> </disk> <disk type="file" device="cdrom"> <driver name="qemu" type="raw"/> <target dev="sdb" bus="scsi"/> <readonly/> <alias name="scsi0-0-0-1"/> <address type="drive" controller="0" bus="0" target="0" unit="1"/> </disk> 2.Record libvirt log and execute commands to eject cdrom # virsh change-media q35 sdb --eject Successfully ejected media. 3.Check libvirt log to find if there are any errors about pr daemon 2020-07-21 04:00:25.857+0000: 13960: info : qemuMonitorSend:946 : QEMU_MONITOR_SEND_MSG: mon=0x7f23f80e8060 msg={"execute":"blockdev-del","arguments":{"node-name":"libvirt-1-format"},"id":"libvirt-15"}^M fd=-1 2020-07-21 04:00:25.857+0000: 14032: info : qemuMonitorIOWrite:433 : QEMU_MONITOR_IO_WRITE: mon=0x7f23f80e8060 buf={"execute":"blockdev-del","arguments":{"node-name":"libvirt-1-format"},"id":"libvirt-15"}^M len=91 ret=91 errno=0 2020-07-21 04:00:25.857+0000: 14032: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": {}, "id": "libvirt-15"}] 2020-07-21 04:00:25.857+0000: 14032: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7f23f80e8060 reply={"return": {}, "id": "libvirt-15"} 2020-07-21 04:00:25.858+0000: 13960: debug : qemuMonitorBlockdevDel:4406 : nodename=libvirt-1-storage 2020-07-21 04:00:25.858+0000: 13960: debug : qemuMonitorBlockdevDel:4408 : mon:0x7f23f80e8060 vm:0x55e6614e86a0 fd:32 2020-07-21 04:00:25.858+0000: 13960: info : qemuMonitorSend:946 : QEMU_MONITOR_SEND_MSG: mon=0x7f23f80e8060 msg={"execute":"blockdev-del","arguments":{"node-name":"libvirt-1-storage"},"id":"libvirt-16"}^M fd=-1 2020-07-21 04:00:25.858+0000: 14032: info : qemuMonitorIOWrite:433 : QEMU_MONITOR_IO_WRITE: mon=0x7f23f80e8060 buf={"execute":"blockdev-del","arguments":{"node-name":"libvirt-1-storage"},"id":"libvirt-16"}^M len=92 ret=92 errno=0 2020-07-21 04:00:25.858+0000: 14032: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": {}, "id": "libvirt-16"}] 2020-07-21 04:00:25.858+0000: 14032: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7f23f80e8060 reply={"return": {}, "id": "libvirt-16"} 2020-07-21 04:00:25.858+0000: 13960: debug : qemuMonitorBlockdevTrayClose:4430 : id=scsi0-0-0-1 2020-07-21 04:00:25.858+0000: 13960: debug : qemuMonitorBlockdevTrayClose:4432 : mon:0x7f23f80e8060 vm:0x55e6614e86a0 fd:32 2020-07-21 04:00:25.858+0000: 13960: info : qemuMonitorSend:946 : QEMU_MONITOR_SEND_MSG: mon=0x7f23f80e8060 msg={"execute":"blockdev-close-tray","arguments":{"id":"scsi0-0-0-1"},"id":"libvirt-17"}^M fd=-1 2020-07-21 04:00:25.858+0000: 14032: info : qemuMonitorIOWrite:433 : QEMU_MONITOR_IO_WRITE: mon=0x7f23f80e8060 buf={"execute":"blockdev-close-tray","arguments":{"id":"scsi0-0-0-1"},"id":"libvirt-17"}^M No errors found,work as expected,so verified.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory (virt:8.3 bug fix and enhancement update), and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2020:5137