Bug 1623389 - A race condition issue when unplug the same device twice
Summary: A race condition issue when unplug the same device twice
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux Advanced Virtualization
Classification: Red Hat
Component: libvirt
Version: 8.0
Hardware: x86_64
OS: Linux
medium
medium
Target Milestone: rc
: 8.0
Assignee: Michal Privoznik
QA Contact: jiyan
URL:
Whiteboard:
: 1548053 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-08-29 09:12 UTC by Luyao Huang
Modified: 2021-12-10 17:12 UTC (History)
14 users (show)

Fixed In Version: libvirt-5.3.0-1.el8
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-11-06 07:11:37 UTC
Type: Bug
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2019:3723 0 None None None 2019-11-06 07:11:52 UTC

Description Luyao Huang 2018-08-29 09:12:39 UTC
Description of problem:
A race condition issue when unplug the same device twice:

When unplug a device twice, if libvirtd receive device delete event (caused by the first time unplug) in the second time unplug progress (after lock &vm). Since the device already been marked as removal, qemuDomainSignalDeviceRemoval function will return true and qemuProcessHandleDeviceDeleted won't call the callback function to handle this event. This make device already been removed but still can been found in domain xml.

Version-Release number of selected component (if applicable):
libvirt-4.5.0-7.el7.x86_64

How reproducible:
80%

Steps to Reproduce:
1. attach a shmem device to guest (shmem device is easy to reproduce this issue):

# cat shmem.xml 
    <shmem name='my_shmem0'>
      <model type='ivshmem-plain'/>
      <size unit='M'>4</size>
      <alias name='ua-123'/>
    </shmem>

# virsh attach-device vm1 shmem.xml
Device attached successfully

2. detach it twice use detach-device-alias + detach-device:

# virsh detach-device-alias vm1 ua-123; virsh detach-device vm1 shmem.xml
Device detach request sent successfully

error: Failed to detach device from shmem.xml
error: internal error: unable to execute QEMU command 'device_del': Device 'ua-123' not found

3. the device already been removed in qemu and guest os, but still can see it in xml and cannot unplug it:

# virsh dumpxml vm1
    <shmem name='my_shmem0'>
      <model type='ivshmem-plain'/>
      <size unit='M'>4</size>
      <alias name='ua-123'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x0a' function='0x0'/>
    </shmem>

# virsh detach-device-alias vm1 ua-123
error: Failed to detach device with alias ua-123
error: internal error: unable to execute QEMU command 'device_del': Device 'ua-123' not found


Actual results:

device status is invalid after hit this issue

Expected results:

device cannot been found in xml after receive qemu device remove event

Additional info:

debug log for the 2nd time device unplug:

2018-08-29 03:01:00.044+0000: 24619: debug : virDomainDetachDevice:8187 : dom=0x7fef2c0008c0, (VM: name=vm1, uuid=f98741e7-ddad-4be1-82c0-0ae3655d1c25), xml=    <shmem name='my_shmem0'>
      <model type='ivshmem-plain'/>
      <size unit='M'>4</size>
      <alias name='ua-123'/>
    </shmem>

2018-08-29 03:01:00.044+0000: 24619: debug : qemuDomainObjBeginJobInternal:6609 : Starting job: job=modify agentJob=none asyncJob=none (vm=0x7feec8182330 name=vm1, current job=none agentJob=none async=none)
2018-08-29 03:01:00.044+0000: 24619: debug : qemuDomainObjBeginJobInternal:6658 : Started job: modify (async=none vm=0x7feec8182330 name=vm1)
2018-08-29 03:01:00.045+0000: 24618: debug : qemuMonitorJSONIOProcessLine:197 : Line [{"timestamp": {"seconds": 1535511660, "microseconds": 45473}, "event": "DEVICE_DELETED", "data": {"device": "ua-123", "path": "/machine/peripheral/ua-123"}}]
2018-08-29 03:01:00.045+0000: 24618: info : qemuMonitorJSONIOProcessLine:212 : QEMU_MONITOR_RECV_EVENT: mon=0x7feec4001020 event={"timestamp": {"seconds": 1535511660, "microseconds": 45473}, "event": "DEVICE_DELETED", "data": {"device": "ua-123", "path": "/machine/peripheral/ua-123"}}
2018-08-29 03:01:00.045+0000: 24618: debug : qemuMonitorJSONIOProcessEvent:158 : mon=0x7feec4001020 obj=0x56094ed4c000
2018-08-29 03:01:00.045+0000: 24618: debug : qemuMonitorEmitEvent:1325 : mon=0x7feec4001020 event=DEVICE_DELETED
2018-08-29 03:01:00.045+0000: 24618: debug : qemuProcessHandleEvent:535 : vm=0x7feec8182330
2018-08-29 03:01:00.046+0000: 24619: debug : virQEMUCapsCacheLookup:4761 : Returning caps 0x7feec8011db0 for /usr/libexec/qemu-kvm
2018-08-29 03:01:00.046+0000: 24619: debug : qemuDomainObjEnterMonitorInternal:7050 : Entering monitor (mon=0x7feec4001020 vm=0x7feec8182330 name=vm1)
2018-08-29 03:01:00.046+0000: 24619: debug : qemuMonitorDelDevice:2976 : devalias=ua-123
2018-08-29 03:01:00.046+0000: 24619: debug : qemuMonitorDelDevice:2978 : mon:0x7feec4001020 vm:0x7feec8182330 json:1 fd:23
2018-08-29 03:01:00.046+0000: 24619: debug : qemuMonitorJSONCommandWithFd:305 : Send command '{"execute":"device_del","arguments":{"id":"ua-123"},"id":"libvirt-18"}' for write with FD -1
2018-08-29 03:01:00.046+0000: 24619: info : qemuMonitorSend:1083 : QEMU_MONITOR_SEND_MSG: mon=0x7feec4001020 msg={"execute":"device_del","arguments":{"id":"ua-123"},"id":"libvirt-18"}^M
 fd=-1
2018-08-29 03:01:00.046+0000: 24618: debug : qemuMonitorJSONIOProcessEvent:183 : handle DEVICE_DELETED handler=0x7feef0444aa0 data=0x56094ed49aa0
2018-08-29 03:01:00.046+0000: 24618: debug : qemuMonitorEmitDeviceDeleted:1544 : mon=0x7feec4001020
2018-08-29 03:01:00.046+0000: 24618: debug : qemuProcessHandleDeviceDeleted:1279 : Device ua-123 removed from domain 0x7feec8182330 vm1
2018-08-29 03:01:00.046+0000: 24618: debug : qemuDomainSignalDeviceRemoval:4662 : Removal of device 'ua-123' continues in waiting thread
2018-08-29 03:01:00.046+0000: 24618: info : qemuMonitorIOWrite:551 : QEMU_MONITOR_IO_WRITE: mon=0x7feec4001020 buf={"execute":"device_del","arguments":{"id":"ua-123"},"id":"libvirt-18"}^M
 len=72 ret=72 errno=0
2018-08-29 03:01:00.047+0000: 24618: debug : qemuMonitorJSONIOProcessLine:197 : Line [{"id": "libvirt-18", "error": {"class": "DeviceNotFound", "desc": "Device 'ua-123' not found"}}]
2018-08-29 03:01:00.047+0000: 24618: info : qemuMonitorJSONIOProcessLine:217 : QEMU_MONITOR_RECV_REPLY: mon=0x7feec4001020 reply={"id": "libvirt-18", "error": {"class": "DeviceNotFound", "desc": "Device 'ua-123' not found"}}
2018-08-29 03:01:00.047+0000: 24619: debug : qemuMonitorJSONCommandWithFd:310 : Receive command reply ret=0 rxObject=0x56094ed66760
2018-08-29 03:01:00.047+0000: 24619: debug : qemuMonitorJSONCheckError:385 : unable to execute QEMU command {"execute":"device_del","arguments":{"id":"ua-123"},"id":"libvirt-18"}: {"id":"libvirt-18","error":{"class":"DeviceNotFound","desc":"Device 'ua-123' not found"}}
2018-08-29 03:01:00.047+0000: 24619: error : qemuMonitorJSONCheckError:396 : internal error: unable to execute QEMU command 'device_del': Device 'ua-123' not found
2018-08-29 03:01:00.047+0000: 24619: debug : qemuDomainObjExitMonitorInternal:7073 : Exited monitor (mon=0x7feec4001020 vm=0x7feec8182330 name=vm1)
2018-08-29 03:01:00.047+0000: 24619: debug : qemuDomainObjEndJob:6934 : Stopping job: modify (async=none vm=0x7feec8182330 name=vm1)

Comment 1 Peter Krempa 2019-02-19 17:01:15 UTC
(In reply to Luyao Huang from comment #0)
> Description of problem:
> A race condition issue when unplug the same device twice:

Good analysis.
 
> When unplug a device twice, if libvirtd receive device delete event (caused
> by the first time unplug) in the second time unplug progress (after lock
> &vm). Since the device already been marked as removal,
> qemuDomainSignalDeviceRemoval function will return true and
> qemuProcessHandleDeviceDeleted won't call the callback function to handle
> this event. This make device already been removed but still can been found

The problem is that while the event loop thread handling the event thinks that the finishing steps of unplug will be handled synchronously, the monitor code gets an error and skips the finishing code.

> in domain xml.
>

Comment 2 Michal Privoznik 2019-03-12 15:13:45 UTC
Patches proposed on the list:

https://www.redhat.com/archives/libvir-list/2019-March/msg00753.html

Comment 5 Michal Privoznik 2019-03-15 12:58:18 UTC
I've just merged the patches upstream:

c2bc419131 qemu_hotplug: Fix a rare race condition when detaching a device twice
229a0358f0 qemuMonitorJSONDelDevice: Return -2 on DeviceNotFound error
4cd13478ac qemu_hotplug: Introduce and use qemuDomainDeleteDevice
641438fb75 run: Don't export unnecessary paths

v5.1.0-241-gc2bc419131

Comment 6 Jiri Denemark 2019-04-25 09:23:14 UTC
*** Bug 1548053 has been marked as a duplicate of this bug. ***

Comment 8 jiyan 2019-07-18 02:24:16 UTC
Hi Michal
I tested this bug on libvirt-5.5.0-1.module+el8.1.0+3580+d7f6488d.x86_64; and I found it would be failed to detach device by using detach-device-alias/detach-device twice however the cmds return success.

Version:
libvirt-5.5.0-1.module+el8.1.0+3580+d7f6488d.x86_64
qemu-kvm-4.0.0-5.module+el8.1.0+3622+5812d9bf.x86_64
kernel-4.18.0-115.el8.x86_64

Steps:
1. Prepare a running VM with bootos and confirm the VM boots successfully
# virsh domstate test
running

# virsh dumpxml test |grep "<disk" -A7
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2'/>
      <source file='/var/lib/libvirt/images/RHEL-8.1-x86_64-latest-ovmf.qcow2'/>
      <backingStore/>
      <target dev='vda' bus='virtio'/>
      <alias name='virtio-disk0'/>
      <address type='pci' domain='0x0000' bus='0x03' slot='0x00' function='0x0'/>
    </disk>

# virsh console test
Red Hat Enterprise Linux 8.1 Beta (Ootpa)
Kernel 4.18.0-107.el8.x86_64 on an x86_64

localhost login: root
Password: 

2. Attach disk to VM; check dumpxml and fisk info in guest OS
# cat disk.xml 
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2'/>
      <source file='/var/lib/libvirt/images/test.qcow2'/>
      <target dev='vdb' bus='virtio'/>
      <alias name="ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"/>
    </disk>

# virsh attach-device test disk.xml 
Device attached successfully

# stap /usr/share/doc/libvirt-docs/examples/systemtap/qemu-monitor.stp 
 45.826 > 0x7f1b0c01f3f0 {"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/var/lib/libvirt/images/test.qcow2,format=qcow2,if=none,id=drive-ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"},"id":"libvirt-21"}
 45.828 < 0x7f1b0c01f3f0 {"return": "OK\r\n", "id": "libvirt-21"}
 45.828 > 0x7f1b0c01f3f0 {"execute":"device_add","arguments":{"driver":"virtio-blk-pci","scsi":"off","bus":"pci.5","addr":"0x0","drive":"drive-ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783","id":"ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"},"id":"libvirt-22"}
 45.832 < 0x7f1b0c01f3f0 {"return": {}, "id": "libvirt-22"}
 45.832 > 0x7f1b0c01f3f0 {"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-23"}
 45.833 < 0x7f1b0c01f3f0 {"return": [{"name": "type", "type": "string"}, {"name": "serial0", "type": "child<isa-serial>"}, {"name": "balloon0", "type": "child<virtio-balloon-pci>"}, {"name": "video0", "type": "child<qxl-vga>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "pci.5", "type": "child<pcie-root-port>"}, {"name": "pci.4", "type": "child<pcie-root-port>"}, {"name": "pci.3", "type": "child<pcie-root-port>"}, {"name": "pci.2", "type": "child<pcie-pci-bridge>"}, {"name": "pci.1", "type

# virsh dumpxml test |grep "<disk" -A7
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2'/>
      <source file='/var/lib/libvirt/images/RHEL-8.1-x86_64-latest-ovmf.qcow2'/>
      <backingStore/>
      <target dev='vda' bus='virtio'/>
      <alias name='virtio-disk0'/>
      <address type='pci' domain='0x0000' bus='0x03' slot='0x00' function='0x0'/>
    </disk>
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2'/>
      <source file='/var/lib/libvirt/images/test.qcow2'/>
      <backingStore/>
      <target dev='vdb' bus='virtio'/>
      <alias name='ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783'/>
      <address type='pci' domain='0x0000' bus='0x05' slot='0x00' function='0x0'/>
    </disk>

# virsh console test
# fdisk -l
Disk /dev/vda: 10 GiB, 10737418240 bytes, 20971520 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: gpt
Disk identifier: B8A4B6EF-884A-439B-AABD-7F76BFDFBFAF

Device       Start      End  Sectors  Size Type
/dev/vda1     2048  1230847  1228800  600M EFI System
/dev/vda2  1230848  3327999  2097152    1G Linux filesystem
/dev/vda3  3328000 20969471 17641472  8.4G Linux LVM
...

Disk /dev/vdb: 1 GiB, 1073741824 bytes, 2097152 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes

3. Detach disk twice; check dumpxml and disk info in guest OS
# virsh detach-device-alias test ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783 ; virsh detach-device test disk.xml 
Device detach request sent successfully

Device detached successfully

# stap /usr/share/doc/libvirt-docs/examples/systemtap/qemu-monitor.stp 
 91.876 > 0x7f1b0c01f3f0 {"execute":"device_del","arguments":{"id":"ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"},"id":"libvirt-24"}
 91.877 < 0x7f1b0c01f3f0 {"return": {}, "id": "libvirt-24"}
 91.877 > 0x7f1b0c01f3f0 {"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-25"}
 91.878 < 0x7f1b0c01f3f0 {"return": [{"name": "type", "type": "string"}, {"name": "serial0", "type": "child<isa-serial>"}, {"name": "balloon0", "type": "child<virtio-balloon-pci>"}, {"name": "video0", "type": "child<qxl-vga>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "pci.5", "type": "child<pcie-root-port>"}, {"name": "pci.4", "type": "child<pcie-root-port>"}, {"name": "pci.3", "type": "child<pcie-root-port>"}, {"name": "pci.2", "type": "child<pcie-pci-bridge>"}, {"name": "pci.1", "type
 91.905 > 0x7f1b0c01f3f0 {"execute":"device_del","arguments":{"id":"ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"},"id":"libvirt-26"}
 91.906 < 0x7f1b0c01f3f0 {"return": {}, "id": "libvirt-26"}
 96.906 > 0x7f1b0c01f3f0 {"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-27"}
 96.907 < 0x7f1b0c01f3f0 {"return": [{"name": "type", "type": "string"}, {"name": "serial0", "type": "child<isa-serial>"}, {"name": "balloon0", "type": "child<virtio-balloon-pci>"}, {"name": "video0", "type": "child<qxl-vga>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "pci.5", "type": "child<pcie-root-port>"}, {"name": "pci.4", "type": "child<pcie-root-port>"}, {"name": "pci.3", "type": "child<pcie-root-port>"}, {"name": "pci.2", "type": "child<pcie-pci-bridge>"}, {"name": "pci.1", "type

# virsh dumpxml test |grep "<disk" -A7
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2'/>
      <source file='/var/lib/libvirt/images/RHEL-8.1-x86_64-latest-ovmf.qcow2'/>
      <backingStore/>
      <target dev='vda' bus='virtio'/>
      <alias name='virtio-disk0'/>
      <address type='pci' domain='0x0000' bus='0x03' slot='0x00' function='0x0'/>
    </disk>
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2'/>
      <source file='/var/lib/libvirt/images/test.qcow2'/>
      <backingStore/>
      <target dev='vdb' bus='virtio'/>
      <alias name='ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783'/>
      <address type='pci' domain='0x0000' bus='0x05' slot='0x00' function='0x0'/>
    </disk>

# virsh console test
# fdisk -l
Disk /dev/vda: 10 GiB, 10737418240 bytes, 20971520 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: gpt
Disk identifier: B8A4B6EF-884A-439B-AABD-7F76BFDFBFAF

Device       Start      End  Sectors  Size Type
/dev/vda1     2048  1230847  1228800  600M EFI System
/dev/vda2  1230848  3327999  2097152    1G Linux filesystem
/dev/vda3  3328000 20969471 17641472  8.4G Linux LVM
...

Disk /dev/vdb: 1 GiB, 1073741824 bytes, 2097152 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes

4. Continue to detach
# virsh detach-device-alias test ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783 ; virsh detach-device test disk.xml 
Device detach request sent successfully

Device detached successfully

# virsh detach-device-alias test ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783
Device detach request sent successfully

# virsh detach-device test disk.xml 
error: Failed to detach device from disk.xml
error: operation failed: disk vdb not found

# virsh detach-device-alias test ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783
error: Failed to detach device with alias ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783
error: internal error: no device found with alias ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783

# virsh dumpxml test |grep "<disk" -A7
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2'/>
      <source file='/var/lib/libvirt/images/RHEL-8.1-x86_64-latest-ovmf.qcow2'/>
      <backingStore/>
      <target dev='vda' bus='virtio'/>
      <alias name='virtio-disk0'/>
      <address type='pci' domain='0x0000' bus='0x03' slot='0x00' function='0x0'/>
    </disk>

# stap /usr/share/doc/libvirt-docs/examples/systemtap/qemu-monitor.stp 
 91.876 > 0x7f1b0c01f3f0 {"execute":"device_del","arguments":{"id":"ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"},"id":"libvirt-24"}
 91.877 < 0x7f1b0c01f3f0 {"return": {}, "id": "libvirt-24"}
 91.877 > 0x7f1b0c01f3f0 {"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-25"}
 91.878 < 0x7f1b0c01f3f0 {"return": [{"name": "type", "type": "string"}, {"name": "serial0", "type": "child<isa-serial>"}, {"name": "balloon0", "type": "child<virtio-balloon-pci>"}, {"name": "video0", "type": "child<qxl-vga>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "pci.5", "type": "child<pcie-root-port>"}, {"name": "pci.4", "type": "child<pcie-root-port>"}, {"name": "pci.3", "type": "child<pcie-root-port>"}, {"name": "pci.2", "type": "child<pcie-pci-bridge>"}, {"name": "pci.1", "type
 91.905 > 0x7f1b0c01f3f0 {"execute":"device_del","arguments":{"id":"ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"},"id":"libvirt-26"}
 91.906 < 0x7f1b0c01f3f0 {"return": {}, "id": "libvirt-26"}
 96.906 > 0x7f1b0c01f3f0 {"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-27"}
 96.907 < 0x7f1b0c01f3f0 {"return": [{"name": "type", "type": "string"}, {"name": "serial0", "type": "child<isa-serial>"}, {"name": "balloon0", "type": "child<virtio-balloon-pci>"}, {"name": "video0", "type": "child<qxl-vga>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "pci.5", "type": "child<pcie-root-port>"}, {"name": "pci.4", "type": "child<pcie-root-port>"}, {"name": "pci.3", "type": "child<pcie-root-port>"}, {"name": "pci.2", "type": "child<pcie-pci-bridge>"}, {"name": "pci.1", "type
392.777 > 0x7f1b0c01f3f0 {"execute":"device_del","arguments":{"id":"ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"},"id":"libvirt-28"}
392.778 < 0x7f1b0c01f3f0 {"return": {}, "id": "libvirt-28"}
392.778 > 0x7f1b0c01f3f0 {"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-29"}
392.781 < 0x7f1b0c01f3f0 {"return": [{"name": "type", "type": "string"}, {"name": "serial0", "type": "child<isa-serial>"}, {"name": "balloon0", "type": "child<virtio-balloon-pci>"}, {"name": "video0", "type": "child<qxl-vga>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "pci.5", "type": "child<pcie-root-port>"}, {"name": "pci.4", "type": "child<pcie-root-port>"}, {"name": "pci.3", "type": "child<pcie-root-port>"}, {"name": "pci.2", "type": "child<pcie-pci-bridge>"}, {"name": "pci.1", "type
392.809 > 0x7f1b0c01f3f0 {"execute":"device_del","arguments":{"id":"ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"},"id":"libvirt-30"}
392.810 < 0x7f1b0c01f3f0 {"return": {}, "id": "libvirt-30"}
397.810 > 0x7f1b0c01f3f0 {"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-31"}
397.811 < 0x7f1b0c01f3f0 {"return": [{"name": "type", "type": "string"}, {"name": "serial0", "type": "child<isa-serial>"}, {"name": "balloon0", "type": "child<virtio-balloon-pci>"}, {"name": "video0", "type": "child<qxl-vga>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "pci.5", "type": "child<pcie-root-port>"}, {"name": "pci.4", "type": "child<pcie-root-port>"}, {"name": "pci.3", "type": "child<pcie-root-port>"}, {"name": "pci.2", "type": "child<pcie-pci-bridge>"}, {"name": "pci.1", "type
401.401 > 0x7f1b0c01f3f0 {"execute":"device_del","arguments":{"id":"ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"},"id":"libvirt-32"}
401.402 < 0x7f1b0c01f3f0 {"return": {}, "id": "libvirt-32"}
401.402 > 0x7f1b0c01f3f0 {"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-33"}
401.403 < 0x7f1b0c01f3f0 {"return": [{"name": "type", "type": "string"}, {"name": "serial0", "type": "child<isa-serial>"}, {"name": "balloon0", "type": "child<virtio-balloon-pci>"}, {"name": "video0", "type": "child<qxl-vga>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "pci.5", "type": "child<pcie-root-port>"}, {"name": "pci.4", "type": "child<pcie-root-port>"}, {"name": "pci.3", "type": "child<pcie-root-port>"}, {"name": "pci.2", "type": "child<pcie-pci-bridge>"}, {"name": "pci.1", "type
407.793 ! 0x7f1b0c01f3f0 {"timestamp": {"seconds": 1563416115, "microseconds": 535176}, "event": "DEVICE_DELETED", "data": {"path": "/machine/peripheral/ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783/virtio-backend"}}
407.852 ! 0x7f1b0c01f3f0 {"timestamp": {"seconds": 1563416115, "microseconds": 594614}, "event": "DEVICE_DELETED", "data": {"device": "ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783", "path": "/machine/peripheral/ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"}}
407.853 > 0x7f1b0c01f3f0 {"execute":"human-monitor-command","arguments":{"command-line":"drive_del drive-ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783"},"id":"libvirt-34"}
407.854 < 0x7f1b0c01f3f0 {"return": "Device 'drive-ua-ebde659a-91f4-4cf5-bd67-1cef55cfe783' not found\r\n", "id": "libvirt-34"}

Comment 9 jiyan 2019-07-18 02:26:50 UTC
Same scenarios for interface/disk devices; since RHEL-8 does not support shmem device and it is hard to test memory device, I will not test them.

Version:
qemu-kvm-4.0.0-5.module+el8.1.0+3622+5812d9bf.x86_64
libvirt-5.5.0-1.module+el8.1.0+3580+d7f6488d.x86_64
kernel-4.18.0-115.el8.x86_64

Steps:
# virsh domstate test
running

# virsh dumpxml test |grep "<interface" -A7
    <interface type='network'>
      <mac address='52:54:00:56:ed:98'/>
      <source network='default' portid='bb80c7d4-040c-4d61-a189-f748b8cb40fe' bridge='virbr0'/>
      <target dev='vnet0'/>
      <model type='e1000'/>
      <alias name='net0'/>
      <address type='pci' domain='0x0000' bus='0x02' slot='0x01' function='0x0'/>
    </interface>

# virsh console test
Connected to domain test
Escape character is ^]
# lspci |grep Eth
02:01.0 Ethernet controller: Intel Corporation 82540EM Gigabit Ethernet Controller (rev 03)

# cat interface.xml 
    <interface type='network'>
      <mac address='52:54:00:56:ed:00'/>
      <source network='default'/>
      <model type='e1000'/>
      <alias name="ua-4b26071e-ab3e-4a07-9555-5197f1de3c12"/>
    </interface>

# virsh attach-device test interface.xml 
Device attached successfully

# virsh dumpxml test |grep "<interface" -A7
    <interface type='network'>
      <mac address='52:54:00:56:ed:98'/>
      <source network='default' portid='bb80c7d4-040c-4d61-a189-f748b8cb40fe' bridge='virbr0'/>
      <target dev='vnet0'/>
      <model type='e1000'/>
      <alias name='net0'/>
      <address type='pci' domain='0x0000' bus='0x02' slot='0x01' function='0x0'/>
    </interface>
    <interface type='network'>
      <mac address='52:54:00:56:ed:00'/>
      <source network='default' portid='a3d55ff5-ccd2-473b-b896-74e2b67d7766' bridge='virbr0'/>
      <target dev='vnet1'/>
      <model type='e1000'/>
      <alias name='ua-4b26071e-ab3e-4a07-9555-5197f1de3c12'/>
      <address type='pci' domain='0x0000' bus='0x02' slot='0x03' function='0x0'/>
    </interface>

# virsh console test
Connected to domain test
Escape character is ^]

[root@localhost ~]# lspci |grep Eth
02:01.0 Ethernet controller: Intel Corporation 82540EM Gigabit Ethernet Controller (rev 03)
02:03.0 Ethernet controller: Intel Corporation 82540EM Gigabit Ethernet Controller (rev 03)

# virsh detach-device-alias test ua-4b26071e-ab3e-4a07-9555-5197f1de3c12;virsh detach-device test interface.xml 
Device detach request sent successfully

Device detached successfully

# virsh dumpxml test |grep "<interface" -A7
    <interface type='network'>
      <mac address='52:54:00:56:ed:98'/>
      <source network='default' portid='bb80c7d4-040c-4d61-a189-f748b8cb40fe' bridge='virbr0'/>
      <target dev='vnet0'/>
      <model type='e1000'/>
      <alias name='net0'/>
      <address type='pci' domain='0x0000' bus='0x02' slot='0x01' function='0x0'/>
    </interface>
    <interface type='network'>
      <mac address='52:54:00:56:ed:00'/>
      <source network='default' portid='a3d55ff5-ccd2-473b-b896-74e2b67d7766' bridge='virbr0'/>
      <target dev='vnet1'/>
      <model type='e1000'/>
      <alias name='ua-4b26071e-ab3e-4a07-9555-5197f1de3c12'/>
      <address type='pci' domain='0x0000' bus='0x02' slot='0x03' function='0x0'/>
    </interface>

# virsh detach-device-alias test ua-4b26071e-ab3e-4a07-9555-5197f1de3c12;virsh detach-device test interface.xml 
Device detach request sent successfully

Device detached successfully

# virsh detach-device-alias test ua-4b26071e-ab3e-4a07-9555-5197f1de3c12;virsh detach-device test interface.xml 
Device detach request sent successfully

Device detached successfully

# virsh dumpxml test |grep "<interface" -A7
    <interface type='network'>
      <mac address='52:54:00:56:ed:98'/>
      <source network='default' portid='bb80c7d4-040c-4d61-a189-f748b8cb40fe' bridge='virbr0'/>
      <target dev='vnet0'/>
      <model type='e1000'/>
      <alias name='net0'/>
      <address type='pci' domain='0x0000' bus='0x02' slot='0x01' function='0x0'/>
    </interface>
    <interface type='network'>
      <mac address='52:54:00:56:ed:00'/>
      <source network='default' portid='a3d55ff5-ccd2-473b-b896-74e2b67d7766' bridge='virbr0'/>
      <target dev='vnet1'/>
      <model type='e1000'/>
      <alias name='ua-4b26071e-ab3e-4a07-9555-5197f1de3c12'/>
      <address type='pci' domain='0x0000' bus='0x02' slot='0x03' function='0x0'/>
    </interface>

# virsh console test
Connected to domain test
Escape character is ^]

[root@localhost ~]# lspci |grep Eth
02:01.0 Ethernet controller: Intel Corporation 82540EM Gigabit Ethernet Controller (rev 03)
02:03.0 Ethernet controller: Intel Corporation 82540EM Gigabit Ethernet Controller (rev 03)
[root@localhost ~]# 
[root@localhost ~]# 

# virsh detach-device test interface.xml 
Device detached successfully

# virsh detach-device-alias test ua-4b26071e-ab3e-4a07-9555-5197f1de3c12
error: Failed to detach device with alias ua-4b26071e-ab3e-4a07-9555-5197f1de3c12
error: internal error: no device found with alias ua-4b26071e-ab3e-4a07-9555-5197f1de3c12

# virsh dumpxml test |grep "<interface" -A7
    <interface type='network'>
      <mac address='52:54:00:56:ed:98'/>
      <source network='default' portid='bb80c7d4-040c-4d61-a189-f748b8cb40fe' bridge='virbr0'/>
      <target dev='vnet0'/>
      <model type='e1000'/>
      <alias name='net0'/>
      <address type='pci' domain='0x0000' bus='0x02' slot='0x01' function='0x0'/>
    </interface>

Would you please have a look at it? thank you.

Comment 10 Michal Privoznik 2019-07-18 07:37:41 UTC
(In reply to jiyan from comment #9)
> Would you please have a look at it? thank you.

This looks like the guest took some time to detach the devices. It suceeded detaching one of them in the end. I don't think this is a bug.

Comment 11 Han Han 2019-07-18 10:08:28 UTC
(In reply to jiyan from comment #9)
> Same scenarios for interface/disk devices; since RHEL-8 does not support
> shmem device and it is hard to test memory device, I will not test them.
> 
> Version:
> qemu-kvm-4.0.0-5.module+el8.1.0+3622+5812d9bf.x86_64
> libvirt-5.5.0-1.module+el8.1.0+3580+d7f6488d.x86_64
> kernel-4.18.0-115.el8.x86_64
> 
> Steps:
> # virsh domstate test
> running
> 
> # virsh dumpxml test |grep "<interface" -A7
>     <interface type='network'>
>       <mac address='52:54:00:56:ed:98'/>
>       <source network='default'
> portid='bb80c7d4-040c-4d61-a189-f748b8cb40fe' bridge='virbr0'/>
>       <target dev='vnet0'/>
>       <model type='e1000'/>
>       <alias name='net0'/>
>       <address type='pci' domain='0x0000' bus='0x02' slot='0x01'
> function='0x0'/>
>     </interface>
> 
> # virsh console test
> Connected to domain test
> Escape character is ^]
> # lspci |grep Eth
> 02:01.0 Ethernet controller: Intel Corporation 82540EM Gigabit Ethernet
> Controller (rev 03)
> 
> # cat interface.xml 
>     <interface type='network'>
>       <mac address='52:54:00:56:ed:00'/>
>       <source network='default'/>
>       <model type='e1000'/>
>       <alias name="ua-4b26071e-ab3e-4a07-9555-5197f1de3c12"/>
>     </interface>
> 
> # virsh attach-device test interface.xml 
> Device attached successfully
> 
> # virsh dumpxml test |grep "<interface" -A7
>     <interface type='network'>
>       <mac address='52:54:00:56:ed:98'/>
>       <source network='default'
> portid='bb80c7d4-040c-4d61-a189-f748b8cb40fe' bridge='virbr0'/>
>       <target dev='vnet0'/>
>       <model type='e1000'/>
>       <alias name='net0'/>
>       <address type='pci' domain='0x0000' bus='0x02' slot='0x01'
> function='0x0'/>
>     </interface>
>     <interface type='network'>
>       <mac address='52:54:00:56:ed:00'/>
>       <source network='default'
> portid='a3d55ff5-ccd2-473b-b896-74e2b67d7766' bridge='virbr0'/>
>       <target dev='vnet1'/>
>       <model type='e1000'/>
>       <alias name='ua-4b26071e-ab3e-4a07-9555-5197f1de3c12'/>
>       <address type='pci' domain='0x0000' bus='0x02' slot='0x03'
> function='0x0'/>
>     </interface>
> 
> # virsh console test
> Connected to domain test
> Escape character is ^]
> 
> [root@localhost ~]# lspci |grep Eth
> 02:01.0 Ethernet controller: Intel Corporation 82540EM Gigabit Ethernet
> Controller (rev 03)
> 02:03.0 Ethernet controller: Intel Corporation 82540EM Gigabit Ethernet
> Controller (rev 03)
> 
> # virsh detach-device-alias test
> ua-4b26071e-ab3e-4a07-9555-5197f1de3c12;virsh detach-device test
> interface.xml 
> Device detach request sent successfully
> 
> Device detached successfully
> 
> # virsh dumpxml test |grep "<interface" -A7
>     <interface type='network'>
>       <mac address='52:54:00:56:ed:98'/>
>       <source network='default'
> portid='bb80c7d4-040c-4d61-a189-f748b8cb40fe' bridge='virbr0'/>
>       <target dev='vnet0'/>
>       <model type='e1000'/>
>       <alias name='net0'/>
>       <address type='pci' domain='0x0000' bus='0x02' slot='0x01'
> function='0x0'/>
>     </interface>
>     <interface type='network'>
>       <mac address='52:54:00:56:ed:00'/>
>       <source network='default'
> portid='a3d55ff5-ccd2-473b-b896-74e2b67d7766' bridge='virbr0'/>
>       <target dev='vnet1'/>
>       <model type='e1000'/>
>       <alias name='ua-4b26071e-ab3e-4a07-9555-5197f1de3c12'/>
>       <address type='pci' domain='0x0000' bus='0x02' slot='0x03'
> function='0x0'/>
>     </interface>
> 
> # virsh detach-device-alias test
> ua-4b26071e-ab3e-4a07-9555-5197f1de3c12;virsh detach-device test
> interface.xml 
> Device detach request sent successfully
> 
> Device detached successfully
> 
> # virsh detach-device-alias test
> ua-4b26071e-ab3e-4a07-9555-5197f1de3c12;virsh detach-device test
> interface.xml 
> Device detach request sent successfully
> 
> Device detached successfully
> 
> # virsh dumpxml test |grep "<interface" -A7
>     <interface type='network'>
>       <mac address='52:54:00:56:ed:98'/>
>       <source network='default'
> portid='bb80c7d4-040c-4d61-a189-f748b8cb40fe' bridge='virbr0'/>
>       <target dev='vnet0'/>
>       <model type='e1000'/>
>       <alias name='net0'/>
>       <address type='pci' domain='0x0000' bus='0x02' slot='0x01'
> function='0x0'/>
>     </interface>
>     <interface type='network'>
>       <mac address='52:54:00:56:ed:00'/>
>       <source network='default'
> portid='a3d55ff5-ccd2-473b-b896-74e2b67d7766' bridge='virbr0'/>
>       <target dev='vnet1'/>
>       <model type='e1000'/>
>       <alias name='ua-4b26071e-ab3e-4a07-9555-5197f1de3c12'/>
>       <address type='pci' domain='0x0000' bus='0x02' slot='0x03'
> function='0x0'/>
>     </interface>
> 
> # virsh console test
> Connected to domain test
> Escape character is ^]
> 
> [root@localhost ~]# lspci |grep Eth
> 02:01.0 Ethernet controller: Intel Corporation 82540EM Gigabit Ethernet
> Controller (rev 03)
> 02:03.0 Ethernet controller: Intel Corporation 82540EM Gigabit Ethernet
> Controller (rev 03)
Are u using q35 machinea and NIC attached to PICe? If so, that delay is a expected result. See https://lists.nongnu.org/archive/html/qemu-discuss/2019-05/msg00006.html
> [root@localhost ~]# 
> [root@localhost ~]# 
> 
> # virsh detach-device test interface.xml 
> Device detached successfully
> 
> # virsh detach-device-alias test ua-4b26071e-ab3e-4a07-9555-5197f1de3c12
> error: Failed to detach device with alias
> ua-4b26071e-ab3e-4a07-9555-5197f1de3c12
> error: internal error: no device found with alias
> ua-4b26071e-ab3e-4a07-9555-5197f1de3c12
> 
> # virsh dumpxml test |grep "<interface" -A7
>     <interface type='network'>
>       <mac address='52:54:00:56:ed:98'/>
>       <source network='default'
> portid='bb80c7d4-040c-4d61-a189-f748b8cb40fe' bridge='virbr0'/>
>       <target dev='vnet0'/>
>       <model type='e1000'/>
>       <alias name='net0'/>
>       <address type='pci' domain='0x0000' bus='0x02' slot='0x01'
> function='0x0'/>
>     </interface>
> 
> Would you please have a look at it? thank you.

Comment 12 jiyan 2019-07-19 07:42:48 UTC
Hi @hanhan
Yes, I used a q35 VM, I will notice that in the next test, thank you.

Comment 13 jiyan 2019-07-25 10:22:50 UTC
Verified this bug on libvirt-5.5.0-1.module+el8.1.0+3580+d7f6488d.x86_64

Version:
libvirt-5.5.0-1.module+el8.1.0+3580+d7f6488d.x86_64
qemu-kvm-4.0.0-6.module+el8.1.0+3736+a2aefea3.x86_64
kernel-4.18.0-120.el8.x86_64

Steps: Test the scenario "Attaching disk devices and then detaching disk devices twice for 1000 times" with following scripts.
# virsh domstate race [VM boots successfully here and can login to VM OS.]
running

# cat disk.xml 
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2'/>
      <source file='/var/lib/libvirt/images/test.qcow2'/>
      <target dev='vdb' bus='virtio'/>
      <alias name='ua-d0e6145c-2240-4f90-8def-ec56ec840dab'/>
    </disk>

# cat test.py 
import os
import sys
import re
import subprocess

count = 1
while count < 1001:
    print ("ROUND %s"%(str(count)))
    count = count + 1

    print("****ENV check and preparation****")
    cur_dir = os.popen('cd /root/ ; pwd')
    print(cur_dir.read())

    (output0, err0) = subprocess.Popen('virsh dumpxml race |grep "<disk" |wc -l', stdout=subprocess.PIPE, shell=True).communicate()
    if re.findall("1",output0.decode("utf-8")) is not None:
        print("start test")
    else:
        print("There are more than 1 disk in VM")
        sys.exit(1)

    print("****1st attach****")
    (output1, err1) = subprocess.Popen('virsh attach-device race disk.xml', stdout=subprocess.PIPE, shell=True).communicate()
    (output2, err2) = subprocess.Popen('virsh dumpxml race |grep "<disk" |wc -l', stdout=subprocess.PIPE, shell=True).communicate()
    if re.findall("Device attached successfully", output1.decode("utf-8")) is not None and re.findall("2", output2.decode("utf-8")) is not None:
        print("atach successfully")
    else:
        print("attach fail")
        print(err1)
        sys.exit(1)

    print("****1st detach****")
    (output3, err3) = subprocess.Popen('virsh detach-device-alias race ua-d0e6145c-2240-4f90-8def-ec56ec840dab; sleep 1', stdout=subprocess.PIPE, shell=True).communicate()
    (output4, err4) = subprocess.Popen('virsh dumpxml race |grep "<disk" |wc -l', stdout=subprocess.PIPE, shell=True).communicate()
    if re.findall("Device detach request sent successfully", output3.decode("utf-8")) is not None and re.findall("1", output4.decode("utf-8")) is not None:
        print("1st detach successfully")
    else:
        print("1st detach failed")
        print(output3)
        sys.exit(1)

    print("****2rd detach****")
    (output5, err5) = subprocess.Popen('virsh detach-device race disk.xml; sleep 1', stdout=subprocess.PIPE, shell=True).communicate()
    (output6, err6) = subprocess.Popen('virsh dumpxml race |grep "<disk" |wc -l', stdout=subprocess.PIPE, shell=True).communicate()
    if re.findall("error: Failed to detach device from disk.xml", output5.decode("utf-8")) is not None and re.findall("1", output6.decode("utf-8")) is not None:
        print("2rd detach failed as expected")
    else:
        print("2rd detach should fail")
        print(output5)
        sys.exit(1)

    print("**********************************")

Test result:
For script:
ROUND 1
****ENV check and preparation****
/root

start test
****1st attach****
atach successfully
****1st detach****
1st detach successfully
****2rd detach****
error: Failed to detach device from disk.xml
error: operation failed: disk vdb not found
2rd detach failed as expected

...
**********************************
ROUND 1000
****ENV check and preparation****
/root

start test
****1st attach****
atach successfully
****1st detach****
1st detach successfully
****2rd detach****
error: Failed to detach device from disk.xml
error: operation failed: disk vdb not found
2rd detach failed as expected
**********************************

# virsh console race
Running some cmds is normal.

And test same scenario for interface device, it passed as well.

The test result is expected, move this bug to be verified.

Comment 15 errata-xmlrpc 2019-11-06 07:11:37 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, 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-2019:3723

Comment 16 Dan Zheng 2021-02-10 03:35:32 UTC
Covered in automated test:

# avocado run --vt-type libvirt --vt-machine-type q35 virsh.detach_device..detach_mixed
JOB ID     : d7cc7c3cc1199010608935f6564f40b2146b7ca0
JOB LOG    : /root/avocado/job-results/job-2020-09-21T05.41-d7cc7c3/job.log
 (1/1) type_specific.io-github-autotest-libvirt.virsh.detach_device.normal_test.vm_running_live.disk_test.file_type.detach_mixed: PASS (74.07 s)
RESULTS    : PASS 1 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0 | CANCEL 0
JOB TIME   : 76.54 s


Note You need to log in before you can comment on or make changes to this bug.