This is the transcript of interaction with qemu as seen by libvirt when trying the above steps:

QEMU_MONITORIO_WRITE shows what command libvirt sends, QEMU_MONITORIO_PROCESS shows the responses.


Qemu is started prior to this with (sorry for the extra cruft):
LC_ALL=C LD_LIBRARY_PATH=/home/pipo/libvirt/src/.libs:/usr/lib64 PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/opt/bin:/usr/x86_64-pc-linux-gnu/gcc-bin/4.9.3 HOME=/root USER=root LOGNAME=root QEMU_AUDIO_DRV=spice /home/pipo/git/qemu.git/x86_64-softmmu/qemu-system-x86_64 -name guest=cdtest,debug-threads=on -S -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-2-cdtest/master-key.aes -machine pc-q35-2.7,accel=kvm,usb=off,vmport=off -drive file=/usr/share/OVMF/OVMF_CODE.fd,if=pflash,format=raw,unit=0,readonly=on -drive file=/var/lib/libvirt/qemu/nvram/hpq_VARS.fd,if=pflash,format=raw,unit=1 -m 2048 -realtime mlock=off -smp 1,maxcpus=10,sockets=10,cores=1,threads=1 -uuid 728aa558-deb9-4fe0-86ce-8d306ee5bd3b -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-2-cdtest/monitor.sock,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=discard -no-hpet -no-shutdown -global ICH9-LPC.disable_s3=1 -global ICH9-LPC.disable_s4=1 -boot strict=on -device i82801b11-bridge,id=pci.1,bus=pcie.0,addr=0x1e -device pci-bridge,chassis_nr=2,id=pci.2,bus=pci.1,addr=0x0 -device ich9-usb-ehci1,id=usb,bus=pcie.0,addr=0x1d.0x7 -device ich9-usb-uhci1,masterbus=usb.0,firstport=0,bus=pcie.0,multifunction=on,addr=0x1d -device ich9-usb-uhci2,masterbus=usb.0,firstport=2,bus=pcie.0,addr=0x1d.0x1 -device ich9-usb-uhci3,masterbus=usb.0,firstport=4,bus=pcie.0,addr=0x1d.0x2 -device virtio-serial-pci,id=virtio-serial0,bus=pci.2,addr=0x3 -drive if=none,media=cdrom,id=drive-sata0-0-0,readonly=on -device ide-cd,bus=ide.0,drive=drive-sata0-0-0,id=sata0-0-0,bootindex=1 -netdev tap,fd=24,id=hostnet0,vhost=on,vhostfd=26 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:d6:08:9b,bus=pci.2,addr=0x1 -chardev pty,id=charserial0 -device isa-serial,chardev=charserial0,id=serial0 -chardev socket,id=charchannel0,path=/var/lib/libvirt/qemu/channel/target/domain-2-cdtest/org.qemu.guest_agent.0,server,nowait -device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0 -chardev spicevmc,id=charchannel1,name=vdagent -device virtserialport,bus=virtio-serial0.0,nr=2,chardev=charchannel1,id=channel1,name=com.redhat.spice.0 -device usb-tablet,id=input0,bus=usb.0,port=1 -spice port=5900,addr=127.0.0.1,disable-ticketing,image-compression=off,seamless-migration=on -device qxl-vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vgamem_mb=16,max_outputs=1,bus=pcie.0,addr=0x1 -device intel-hda,id=sound0,bus=pci.2,addr=0x2 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -chardev spicevmc,id=charredir0,name=usbredir -device usb-redir,chardev=charredir0,id=redir0,bus=usb.0,port=2 -chardev spicevmc,id=charredir1,name=usbredir -device usb-redir,chardev=charredir1,id=redir1,bus=usb.0,port=3 -incoming defer -device virtio-balloon-pci,id=balloon0,bus=pci.2,addr=0x4 -msg timestamp=on

<interaction prior to start of the migration is trimmed>
QEMU_MONITORIO_WRITE: mon=0x7fe3f800f990 buf={"execute":"migrate-incoming","arguments":{"uri":"fd:20"},"id":"libvirt-17"}
QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"timestamp": {"seconds": 1473090477, "microseconds": 156250}, "event": "MIGRATION", "data": {"status": "setup"}}
QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"return": {}, "id": "libvirt-17"}
QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"timestamp": {"seconds": 1473090477, "microseconds": 156357}, "event": "MIGRATION", "data": {"status": "active"}}
QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"timestamp": {"seconds": 1473090477, "microseconds": 457640}, "event": "VSERPORT_CHANGE", "data": {"open": false, "id": "channel0"}}
QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"timestamp": {"seconds": 1473090477, "microseconds": 457801}, "event": "MIGRATION", "data": {"status": "completed"}}

Note that events are working.

QEMU_MONITORIO_WRITE: mon=0x7fe3f800f990 buf={"execute":"cont","id":"libvirt-18"}
QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"timestamp": {"seconds": 1473090477, "microseconds": 478639}, "event": "RESUME"}
QEMU_MONITORIO_WRITE: mon=0x7fe3f800f990 buf={"execute":"query-block","id":"libvirt-19"}

I've manually issued a query-block to see the state.

QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"return": [{"device": "pflash0", "locked": false, "removable": false, "inserted": {"iops_rd": 0, "detect_zeroes": "off", "image": {"virtual-size": 1966080, "filename": "/usr/share/OVMF/OVMF_CODE.fd", "format": "raw", "actual-size": 1966080, "dirty-flag": false}, "iops_wr": 0, "ro": true, "node-name": "#block108", "backing_file_depth": 0, "drv": "raw", "iops": 0, "bps_wr": 0, "write_threshold": 0, "encrypted": false, "bps": 0, "bps_rd": 0, "cache": {"no-flush": false, "direct": false, "writeback": true}, "file": "/usr/share/OVMF/OVMF_CODE.fd", "encryption_key_missing": false}, "type": "unknown"}, {"device": "pflash1", "locked": false, "removable": false, "inserted": {"iops_rd": 0, "detect_zeroes": "off", "image": {"virtual-size": 131072, "filename": "/var/lib/libvirt/qemu/nvram/hpq_VARS.fd", "format": "raw", "actual-size": 131072, "dirty-flag": false}, "iops_wr": 0, "ro": false, "node-name": "#block313", "backing_file_depth": 0, "drv": "raw", "iops": 0, "bps_wr": 0, "write_threshold": 0, "encrypted": false,  len=1023
QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"return": [{"device": "pflash0", "locked": false, "removable": false, "inserted": {"iops_rd": 0, "detect_zeroes": "off", "image": {"virtual-size": 1966080, "filename": "/usr/share/OVMF/OVMF_CODE.fd", "format": "raw", "actual-size": 1966080, "dirty-flag": false}, "iops_wr": 0, "ro": true, "node-name": "#block108", "backing_file_depth": 0, "drv": "raw", "iops": 0, "bps_wr": 0, "write_threshold": 0, "encrypted": false, "bps": 0, "bps_rd": 0, "cache": {"no-flush": false, "direct": false, "writeback": true}, "file": "/usr/share/OVMF/OVMF_CODE.fd", "encryption_key_missing": false}, "type": "unknown"}, {"device": "pflash1", "locked": false, "removable": false, "inserted": {"iops_rd": 0, "detect_zeroes": "off", "image": {"virtual-size": 131072, "filename": "/var/lib/libvirt/qemu/nvram/hpq_VARS.fd", "format": "raw", "actual-size": 131072, "dirty-flag": false}, "iops_wr": 0, "ro": false, "node-name": "#block313", "backing_file_depth": 0, "drv": "raw", "iops": 0, "bps_wr": 0, "write_threshold": 0, "encrypted": false, "bps": 0, "bps_rd": 0, "cache": {"no-flush": false, "direct": false, "writeback": true}, "file": "/var/lib/libvirt/qemu/nvram/hpq_VARS.fd", "encryption_key_missing": false}, "type": "unknown"}, {"io-status": "ok", "device": "drive-sata0-0-0", "locked": true, "removable": true, "tray_open": false, "type": "unknown"}], "id": "libvirt-19"}

Cdrom is closed and locked.

QEMU_MONITORIO_WRITE: mon=0x7fe3f800f990 buf={"execute":"eject","arguments":{"device":"drive-sata0-0-0","force":false},"id":"libvirt-20"}
QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"id": "libvirt-20", "error": {"class": "GenericError", "desc": "Device 'drive-sata0-0-0' is locked and force was not specified, wait for tray to open and try again"}}

Eject is called and returns error. The guest ejects the drive as it got a notification.

QEMU_MONITORIO_WRITE: mon=0x7fe3f800f990 buf={"execute":"query-block","id":"libvirt-21"}

I've issued another query-block a few seconds later.

QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"return": [{"device": "pflash0", "locked": false, "removable": false, "inserted": {"iops_rd": 0, "detect_zeroes": "off", "image": {"virtual-size": 1966080, "filename": "/usr/share/OVMF/OVMF_CODE.fd", "format": "raw", "actual-size": 1966080, "dirty-flag": false}, "iops_wr": 0, "ro": true, "node-name": "#block108", "backing_file_depth": 0, "drv": "raw", "iops": 0, "bps_wr": 0, "write_threshold": 0, "encrypted": false, "bps": 0, "bps_rd": 0, "cache": {"no-flush": false, "direct": false, "writeback": true}, "file": "/usr/share/OVMF/OVMF_CODE.fd", "encryption_key_missing": false}, "type": "unknown"}, {"device": "pflash1", "locked": false, "removable": false, "inserted": {"iops_rd": 0, "detect_zeroes": "off", "image": {"virtual-size": 131072, "filename": "/var/lib/libvirt/qemu/nvram/hpq_VARS.fd", "format": "raw", "actual-size": 131072, "dirty-flag": false}, "iops_wr": 0, "ro": false, "node-name": "#block313", "backing_file_depth": 0, "drv": "raw", "iops": 0, "bps_wr": 0, "write_threshold": 0, "encrypted": false,  len=1023
QEMU_MONITORIO_PROCESS: mon=0x7fe3f800f990 buf={"return": [{"device": "pflash0", "locked": false, "removable": false, "inserted": {"iops_rd": 0, "detect_zeroes": "off", "image": {"virtual-size": 1966080, "filename": "/usr/share/OVMF/OVMF_CODE.fd", "format": "raw", "actual-size": 1966080, "dirty-flag": false}, "iops_wr": 0, "ro": true, "node-name": "#block108", "backing_file_depth": 0, "drv": "raw", "iops": 0, "bps_wr": 0, "write_threshold": 0, "encrypted": false, "bps": 0, "bps_rd": 0, "cache": {"no-flush": false, "direct": false, "writeback": true}, "file": "/usr/share/OVMF/OVMF_CODE.fd", "encryption_key_missing": false}, "type": "unknown"}, {"device": "pflash1", "locked": false, "removable": false, "inserted": {"iops_rd": 0, "detect_zeroes": "off", "image": {"virtual-size": 131072, "filename": "/var/lib/libvirt/qemu/nvram/hpq_VARS.fd", "format": "raw", "actual-size": 131072, "dirty-flag": false}, "iops_wr": 0, "ro": false, "node-name": "#block313", "backing_file_depth": 0, "drv": "raw", "iops": 0, "bps_wr": 0, "write_threshold": 0, "encrypted": false, "bps": 0, "bps_rd": 0, "cache": {"no-flush": false, "direct": false, "writeback": true}, "file": "/var/lib/libvirt/qemu/nvram/hpq_VARS.fd", "encryption_key_missing": false}, "type": "unknown"}, {"io-status": "ok", "device": "drive-sata0-0-0", "locked": false, "removable": true, "tray_open": true, "type": "unknown"}], "id": "libvirt-21"}

Note that the tray is now open but the DEVICE_TRAY_MOVED event was not delivered.

Not able to reproduce manually using QEMU directly; I tried a normal eject and an eject after I moved the CDROM iso unceremoniously out from under QEMU but always got the event. I didn't test with migration/save/load, so I assume that's the secret sauce.

What's libvirt doing for save/restore? is that savevm / loadvm?
What's the flow look like here? Normally I'd migrate to a VM that already has the ISO loaded, but you're moving the ISO away before the restore ... I'm not actually sure what this does to QEMU.

Can you enlighten me? Does this mean you're not actually giving QEMU an ISO when you re-launch it, but then you do a loadvm to load the state from when it was open when you saved?

(In reply to John Snow from comment #4)
> Not able to reproduce manually using QEMU directly; I tried a normal eject
> and an eject after I moved the CDROM iso unceremoniously out from under QEMU
> but always got the event. I didn't test with migration/save/load, so I
> assume that's the secret sauce.

Exactly. I think that migration is the secret thing, as we start qemu without the image source (as it's missing) but load a migration stream that had a media in it.

> What's libvirt doing for save/restore? is that savevm / loadvm?

save/restore is basically migration to/from file

> What's the flow look like here? Normally I'd migrate to a VM that already
> has the ISO loaded, but you're moving the ISO away before the restore ...
> I'm not actually sure what this does to QEMU.

We start the destination qemu with an empty drive but migrate in a image with a full drive.

> Can you enlighten me? Does this mean you're not actually giving QEMU an ISO
> when you re-launch it, but then you do a loadvm to load the state from when
> it was open when you saved?

exactly

(1) I am super inclined to say that this is not a supported use case because from the perspective of the guest, state has Magically Changed(tm) and we cannot guarantee the behavior of the guest at that point.

(2) Here's the problem:

in cmd_start_stop_unit, we invoke blk_flush, which in turn invokes bdrv_flush ONLY IF we actually have a medium in the tray.

Because we started QEMU without a medium, bdrv_eject doesn't get called and so the event does not get emitted. The device model acknowledges it sent a request to eject to the QEMU internals, but the QEMU internals did nothing because there's nothing to do.

The fix here is unclear; if you want this to be a blocker I think you need to justify this use case beyond "Well, it used to work."

Edit above: I'm multitasking, replace "blk_flush" and "bdrv_flush" by "blk_eject" and "bdrv_eject," thanks.


Some analysis:

If a cdrom is inserted/ejected when the drive is not locked OR we have forced the CDROM tray open; we rely on:

blk_dev_change_media_cb -> ide_cd_change_cb

to change the tray state (ide_cd...) and send the event (blk_dev_...). However, if the eject is guest-initiated as it would be for a hardware request to eject (what QEMU is doing when you qmp_eject with a lock), we go through

cmd_start_stop_unit;

which changes the tray state manually and relies on blk_eject to send the event. However, this is slightly bogus because this means that if I open and close the tray from the guest with no medium in tray, we will never see TRAY_MOVED events.

I probably need to remove the tray notification from bdrv_eject and add in the request somewhere in the device model instead. 

Another interesting point is that ide_cd_change_cb is never invoked for guest-origin requests; in practice this seems to be fine but I would much rather have a model where *all* tray events must pass through the device model, which would include a common callback for both guest-and-hw originating requests.

I am not sure if I can prioritize this as a 7.3 blocker unless some compelling evidence is presented otherwise, though I'll acknowledge there is a minor bug in QEMU.

Retest with qemu-kvm-rhev-2.6.0-21.el7.x86_64 and qemu-kvm-rhev-2.3.0-31.el7_2.21.x86_64.
 
It is reproducible with qemu-kvm-rhev-2.6.0-21.el7.x86_64 but not reproducible with qemu-kvm-rhev-2.3.0-31.el7_2.21.x86_64. So it's a regression.
 
*************************************************************
Reproducible with qemu-kvm-rhev-2.6.0-21.el7.x86_64.
 
Version-Release number of selected component (if applicable):
libvirt-2.0.0-5.el7.x86_64
qemu-kvm-rhev-2.6.0-21.el7.x86_64
 
How reproducible:
100%
 
Test steps are same as comment 0.
 
Actual results:
[root@hp-dl585g7-04 home]# virsh update-device bug cd.xml
error: Failed to update device from cd.xml
error: internal error: unable to execute QEMU command 'eject': Device 'drive-ide0-1-0' is locked and force was not specified, wait for tray to open and try again
[root@hp-dl585g7-04 home]# virsh update-device bug cd.xml
error: Failed to update device from cd.xml
error: internal error: timed out waiting for disk tray status update
 
Libvirt log file is as attachment "libvirtd-2.6.0-21.log".
 
*************************************************************
Not reproducible with qemu-kvm-rhev-2.3.0-31.el7_2.21.x86_64.
 
Version-Release number of selected component (if applicable):
libvirt-2.0.0-5.el7.x86_64
qemu-kvm-rhev-2.3.0-31.el7_2.21.x86_64
 
Test steps are same as comment 0.
 
Actual results:
[root@hp-dl585g7-04 home]# virsh update-device bug cd.xml
Device updated successfully
 
Libvirt log file is as attachment "libvirtd-2.3.0-31.log".

Created attachment 1198879 [details]
libvirtd-2.3.0-31.log

Created attachment 1198880 [details]
libvirtd-2.6.0-21.log

(In reply to John Snow from comment #9)
> Edit above: I'm multitasking, replace "blk_flush" and "bdrv_flush" by
> "blk_eject" and "bdrv_eject," thanks.
> 
> 
> Some analysis:
> 
> If a cdrom is inserted/ejected when the drive is not locked OR we have
> forced the CDROM tray open; we rely on:
> 
> blk_dev_change_media_cb -> ide_cd_change_cb
> 
> to change the tray state (ide_cd...) and send the event (blk_dev_...).
> However, if the eject is guest-initiated as it would be for a hardware
> request to eject (what QEMU is doing when you qmp_eject with a lock), we go
> through
> 
> cmd_start_stop_unit;
> 
> which changes the tray state manually and relies on blk_eject to send the
> event. However, this is slightly bogus because this means that if I open and
> close the tray from the guest with no medium in tray, we will never see
> TRAY_MOVED events.
> 
> I probably need to remove the tray notification from bdrv_eject and add in
> the request somewhere in the device model instead. 

Yep, it doesn't make much sense to base the tray events on the presence of the medium.

> Another interesting point is that ide_cd_change_cb is never invoked for
> guest-origin requests; in practice this seems to be fine but I would much
> rather have a model where *all* tray events must pass through the device
> model, which would include a common callback for both guest-and-hw
> originating requests.
> 
> I am not sure if I can prioritize this as a 7.3 blocker unless some
> compelling evidence is presented otherwise, though I'll acknowledge there is
> a minor bug in QEMU.

Well, the thing is that this specific use case breaks kind of horribly with libvirt if you don't happen to force the ejection on the first attempt. We are waiting for the TRAY_MOVED event even if we force the ejection (btw, that works properly even for empty drive).

I've posted patches that ignore the waiting for the tray.

At any rate I'm not suggesting this is a very common issue so I won't insist on making this a blocker.

Fixed upstream in c47ee043dc2cc85da710e87524144a720598c096,
included in downstream rebase to QEMU 2.8.0.

Verified, it has been resolved, change its status to "Verified".

Test Version:
  kernel verison:3.10.0-561.el7.x86_64
  qemu-kvm-rhev version:qemu-kvm-rhev-2.8.0-4.el7.x86_64

Test Steps:
 1.Start a libvirt domain "test" with cdrom
    ......
    <disk type='file' device='cdrom'>
      <driver name='qemu' type='raw'/>
      <source file='/home/winutils.iso' startupPolicy='requisite' />
      <target dev='hdb' bus='ide'/>
      <readonly/>
      <alias name='ide0-0-0'/>
      <address type='drive' controller='0' bus='0' target='0' unit='1'/>
    </disk>

 2.Move cdrom image away
   # mv winutils.iso winutils.iso.bak

 3.Save guest
   # virsh save test test.save

 4.Restore guest
   # virsh restore test.save

 5.Check if the source iso dropped
   # virsh dumpxml test | grep disk -A 9
   ......
    <disk type='file' device='cdrom'>
      <driver name='qemu' type='raw'/>
      <source startupPolicy='requisite'/>
      <target dev='hdb' bus='ide'/>
      <readonly/>
      <alias name='ide0-0-0'/>
      <address type='drive' controller='0' bus='0' target='0' unit='1'/>
    </disk>

 6.Prepare a new ISO.
   # cat cdrom.xml
   <disk type='file' device='cdrom'>
        <driver name='qemu' type='raw'/>
        <source file='/home/b.iso' startupPolicy='requisite' />
        <target dev='hdb' bus='ide'/>
        <readonly/>
   </disk> 

 7.Update it to guest
  # virsh update-device test cdrom.xml  ---->Device updated successfully

 8.Check it in guest.
  # mount -o loop /dev/sr0 /mnt
  # ls /mnt/

Test Result:
 Data display  in step8.

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, 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/RHSA-2017:2392

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, 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/RHSA-2017:2392

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, 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/RHSA-2017:2392

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, 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/RHSA-2017:2392

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, 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/RHSA-2017:2392

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, 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/RHSA-2017:2392