Bug 1814486

Summary: Error "object 'pr-helper0' not found" happens when updating cdrom
Product: Red Hat Enterprise Linux Advanced Virtualization Reporter: Han Han <hhan>
Component: libvirtAssignee: Peter Krempa <pkrempa>
Status: CLOSED ERRATA QA Contact: gaojianan <jgao>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 8.2CC: jdenemar, lmen, pkrempa, virt-maint, xuzhang
Target Milestone: rcKeywords: Triaged
Target Release: 8.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: libvirt-6.2.0-1.el8 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-11-17 17:47:36 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
Libvirtd log of step2
none
domain xml, libvirtd conf, qemu conf none

Description Han Han 2020-03-18 02:03:04 UTC
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

Comment 1 Peter Krempa 2020-03-18 07:57:35 UTC
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.

Comment 2 Han Han 2020-03-18 09:30:34 UTC
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

Comment 3 Peter Krempa 2020-03-18 10:41:03 UTC
Oh, I see now. The media changing code always tries to remove the pr daemon even if the backing chain didn't have it.

Comment 4 Peter Krempa 2020-03-19 09:20:38 UTC
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.

Comment 7 gaojianan 2020-07-21 04:06:52 UTC
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.

Comment 10 errata-xmlrpc 2020-11-17 17:47:36 UTC
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