RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1141732 - wrong QMP argument 'id' when detaching iscsi hostdev
Summary: wrong QMP argument 'id' when detaching iscsi hostdev
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: libvirt
Version: 7.1
Hardware: x86_64
OS: Linux
medium
medium
Target Milestone: rc
: ---
Assignee: John Ferlan
QA Contact: Virtualization Bugs
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-09-15 10:50 UTC by Jincheng Miao
Modified: 2015-03-05 07:44 UTC (History)
6 users (show)

Fixed In Version: libvirt-1.2.8-5.el7
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-03-05 07:44:33 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2015:0323 0 normal SHIPPED_LIVE Low: libvirt security, bug fix, and enhancement update 2015-03-05 12:10:54 UTC

Description Jincheng Miao 2014-09-15 10:50:35 UTC 
Description of problem:
When detaching iscsi hostdev, libvirtd puts a wrong QMP argument 'id' for QEMU command '__com.redhat_drive_del'.

Version-Release number of selected component (if applicable):
libvirt-1.2.8-2.el7.x86_64
qemu-kvm-rhev-2.1.0-3.el7.x86_64

How reproducible:
100%

Steps to Reproduce:
1. add iscsi hostdev to guest
# virsh edit r7a
...
    <hostdev mode='subsystem' type='scsi' managed='no'>
      <source protocol='iscsi' name='iqn.2014-09.com.jmiao/1'>
        <host name='xx.xx.xx.xx' port='3260'/>
      </source>
      <address type='drive' controller='0' bus='0' target='0' unit='0'/>
    </hostdev>
...

2. start guest
# virsh start r7a

3. detach-device
# virsh detach-device r7a iscsi-hostdev.xml
error: Failed to detach device from iscsi-hostdev.xml
error: internal error: unable to execute QEMU command '__com.redhat_drive_del': An undefined error has occurred

From qemu-monitor.stp:

252910.059 > 0x7fd9fc009560 {"execute":"device_del","arguments":{"id":"hostdev0"},"id":"libvirt-9"}
252910.062 ! 0x7fd9fc009560 {"timestamp": {"seconds": 1410502094, "microseconds": 470154}, "event": "DEVICE_DELETED", "data": {"device": "hostdev0", "path": "/machine/peripheral/hostdev0"}}
252910.063 < 0x7fd9fc009560 {"return": {}, "id": "libvirt-9"}
252910.064 > 0x7fd9fc009560 {"execute":"__com.redhat_drive_del","arguments":{"id":"file=iscsi://xx.xx.xx.xx:3260/iqn.2014-09.com.jmiao/1,if=none,format=raw,id=drive-hostdev0"},"id":"libvirt-10"}
252910.069 < 0x7fd9fc009560 {"id": "libvirt-10", "error": {"class": "GenericError", "desc": "An undefined error has occurred"}}
252910.069 > 0x7fd9fc009560 {"execute":"device_add","arguments":{"driver":"scsi-generic","bus":"scsi0.0","channel":"0","scsi-id":"0","lun":"0","drive":"drive-hostdev0","id":"hostdev0"},"id":"libvirt-11"}
252910.074 < 0x7fd9fc009560 {"id": "libvirt-11", "error": {"class": "GenericError", "desc": "Property 'scsi-generic.drive' can't find value 'drive-hostdev0'"}}

We could see:
252910.064 > 0x7fd9fc009560 {"execute":"__com.redhat_drive_del","arguments":{"id":"file=iscsi://xx.xx.xx.xx:3260/iqn.2014-09.com.jmiao/1,if=none,format=raw,id=drive-hostdev0"},"id":"libvirt-10"}
argument 'id' is "file=iscsi://xx.xx.xx.xx:3260/iqn.2014-09.com.jmiao/1,if=none,format=raw,id=drive-hostdev0",
but I thought it should be just hostdev0.
Comment 1 John Ferlan 2014-09-23 19:01:01 UTC 
The iSCSI hostdev code was modeled after the disk/scsi/lun code, but takes a slight different path on hot plug/unplug.

I enabled default debugging in libvirtd.conf and restarted libvirtd

log_level = 1
log_filters="3:remote 4:event 3:json 3:rpc"
log_outputs="1:file:/var/log/libvirt/libvirtd.log"


2014-09-22 23:25:52.008+0000: 15810: debug : virDomainDetachDevice:10477 : dom=0x7fb444000dc0, (VM: name=f18-hostdev-iscsi, uuid=12dc66ad-989a-4919-9fda-ad5c0950539f), xml=<hostdev mode='subsystem' type='scsi'>
  <source protocol='iscsi' name='iqn.2013-12.com.example:iscsi-chap-nopool/2'>
    <host name='192.168.122.1' port='3260'/>
    <auth username='redhat'>
      <secret type='iscsi' usage='libvirtiscsi'/>
    </auth>
  </source>
  <address type='drive' controller='0' bus='0' target='2' unit='5'/>
</hostdev>

...
2014-09-22 23:25:52.008+0000: 15810: debug : qemuDomainObjBeginJobInternal:1288 : Starting job: modify (async=none vm=0x7fb440001690 name=f18-hostdev-iscsi)
...
2014-09-22 23:25:52.009+0000: 15810: debug : qemuMonitorDelDevice:3030 : mon=0x7fb44800fa10 devalias=hostdev1
2014-09-22 23:25:52.009+0000: 15810: debug : qemuMonitorSend:972 : QEMU_MONITOR_SEND_MSG: mon=0x7fb44800fa10 msg={"execute":"device_del","arguments":{"id":"hostdev1"},"id":"libvirt-9"}^M
 fd=-1
...
2014-09-22 23:25:52.009+0000: 15808: debug : qemuMonitorIOWrite:503 : QEMU_MONITOR_IO_WRITE: mon=0x7fb44800fa10 buf={"execute":"device_del","arguments":{"id":"hostdev1"},"id":"libvirt-9"}^M
...
2014-09-22 23:25:52.010+0000: 15808: debug : qemuMonitorIOProcess:399 : QEMU_MONITOR_IO_PROCESS: mon=0x7fb44800fa10 buf={"timestamp": {"seconds": 1411428352, "microseconds": 10606}, "event": "DEVICE_DELETED", "data": {"device": "hostdev1", "path": "/machine/peripheral/hostdev1"}}^M
 len=162
...
2014-09-22 23:25:52.010+0000: 15808: debug : qemuMonitorEmitDeviceDeleted:1382 : mon=0x7fb44800fa10
...
2014-09-22 23:25:52.010+0000: 15808: debug : qemuProcessHandleDeviceDeleted:1460 : Device hostdev1 removed from domain 0x7fb440001690 f18-hostdev-iscsi
...
2014-09-22 23:25:52.011+0000: 15808: debug : qemuMonitorIOProcess:399 : QEMU_MONITOR_IO_PROCESS: mon=0x7fb44800fa10 buf={"return": {}, "id": "libvirt-9"}^M
 len=35
...
2014-09-22 23:25:52.011+0000: 15810: debug : qemuMonitorDriveDel:3011 : mon=0x7fb44800fa10 drivestr=file=iscsi://redhat:redhat.122.1:3260/iqn.2013-12.com.example%3Aiscsi-chap-nopool/2,if=none,format=raw,id=drive-hostdev1
2014-09-22 23:25:52.011+0000: 15810: debug : qemuMonitorTextDriveDel:2635 : TextDriveDel drivestr=file=iscsi://redhat:redhat.122.1:3260/iqn.2013-12.com.example%3Aiscsi-chap-nopool/2,if=none,format=raw,id=drive-hostdev1
2014-09-22 23:25:52.011+0000: 15810: debug : qemuMonitorSend:972 : QEMU_MONITOR_SEND_MSG: mon=0x7fb44800fa10 msg={"execute":"human-monitor-command","arguments":{"command-line":"drive_del file=iscsi://redhat:redhat.122.1:3260/iqn.2013-12.com.example%3Aiscsi-chap-nopool/2,if=none,format=raw,id=drive-hostdev1"},"id":"libvirt-10"}^M
 fd=-1
...
2014-09-22 23:25:52.016+0000: 15808: debug : qemuMonitorIOProcess:399 : QEMU_MONITOR_IO_PROCESS: mon=0x7fb44800fa10 buf={"return": "2014-09-22T23:25:52.016286Z Device 'file=iscsi://redhat:redhat.122.1:3260/iqn.2013-12.com.example%3Aiscsi-chap-nopool/2,if=none,format=raw,id=drive-hostdev1' not found\r\n", "id": "libvirt-10"}^M
 len=215
2014-09-22 23:25:52.016+0000: 15808: debug : virObjectUnref:259 : OBJECT_UNREF: obj=0x7fb44800fa10
2014-09-22 23:25:52.016+0000: 15810: error : qemuMonitorTextDriveDel:2659 : operation failed: deleting file=iscsi://redhat:redhat.122.1:3260/iqn.2013-12.com.example%3Aiscsi-chap-nopool/2,if=none,format=raw,id=drive-hostdev1 drive failed: 2014-09-22T23:25:52.016286Z Device 'file=iscsi://redhat:redhat.122.1:3260/iqn.2013-12.com.example%3Aiscsi-chap-nopool/2,if=none,format=raw,id=drive-hostdev1' not found^M
...


Strange - the "-device" was deleted and the code then went to remove the "-drive" as well... Compared this to the disk/scsi/lun path:

2014-09-22 23:38:38.604+0000: 15812: debug : virDomainDetachDevice:10477 : dom=0x7fb43c0008c0, (VM: name=f18-disk-iscsi, uuid=d76c66d6-2f8d-42cc-a745-5bad91f5ee70), xml=<disk type='network' device='disk'>
  <driver name='qemu' type='raw'/>
  <auth username='redhat'>
    <secret type='iscsi' usage='libvirtiscsi'/>
  </auth>
  <source protocol='iscsi' name='iqn.2013-12.com.example:iscsi-chap-nopool/2'>
    <host name='192.168.122.1' port='3260'/>
  </source>
  <target dev='vdc' bus='virtio'/>
  <address type='pci' domain='0x0000' bus='0x00' slot='0x0a' function='0x0'/>
</disk>
...
2014-09-22 23:38:38.604+0000: 15812: debug : qemuMonitorDelDevice:3030 : mon=0x7fb448006790 devalias=virtio-disk2
2014-09-22 23:38:38.604+0000: 15812: debug : qemuMonitorSend:972 : QEMU_MONITOR_SEND_MSG: mon=0x7fb448006790 msg={"execute":"device_del","arguments":{"id":"virtio-disk2"},"id":"libvirt-9"}^M
 fd=-1
...
2014-09-22 23:38:38.604+0000: 15808: debug : qemuMonitorIOWrite:503 : QEMU_MONITOR_IO_WRITE: mon=0x7fb448006790 buf={"execute":"device_del","arguments":{"id":"virtio-disk2"},"id":"libvirt-9"}^M
 len=77 ret=77 errno=0
...
2014-09-22 23:38:38.618+0000: 15808: debug : qemuMonitorIOProcess:399 : QEMU_MONITOR_IO_PROCESS: mon=0x7fb448006790 buf={"timestamp": {"seconds": 1411429118, "microseconds": 617973}, "event": "DEVICE_DELETED", "data": {"path": "/machine/peripheral/virtio-disk2/virtio-backend"}}^M
 len=160
2014-09-22 23:38:38.618+0000: 15808: debug : qemuMonitorEmitEvent:1186 : mon=0x7fb448006790 event=DEVICE_DELETED
...
2014-09-22 23:38:38.623+0000: 15808: debug : qemuProcessHandleDeviceDeleted:1460 : Device virtio-disk2 removed from domain 0x7fb44c1d5540 f18-disk-iscsi
...
2014-09-22 23:38:38.623+0000: 15812: debug : qemuMonitorDriveDel:3011 : mon=0x7fb448006790 drivestr=drive-virtio-disk2
2014-09-22 23:38:38.623+0000: 15812: debug : qemuMonitorTextDriveDel:2635 : TextDriveDel drivestr=drive-virtio-disk2
2014-09-22 23:38:38.623+0000: 15812: debug : qemuMonitorSend:972 : QEMU_MONITOR_SEND_MSG: mon=0x7fb448006790 msg={"execute":"human-monitor-command","arguments":{"command-line":"drive_del drive-virtio-disk2"},"id":"libvirt-10"}^M
 fd=-1
...
2014-09-22 23:38:38.623+0000: 15808: debug : qemuMonitorIOWrite:503 : QEMU_MONITOR_IO_WRITE: mon=0x7fb448006790 buf={"execute":"human-monitor-command","arguments":{"command-line":"drive_del drive-virtio-disk2"},"id":"libvirt-10"}^M
 len=115 ret=115 errno=0
...
2014-09-22 23:38:38.626+0000: 15812: error : qemuMonitorTextDriveDel:2659 : operation failed: deleting drive-virtio-disk2 drive failed: 2014-09-22T23:38:38.626229Z Device 'drive-virtio-disk2' not found^M



Hmm...  strange - same "issue", but it doesn't cause failure...  Off to the code...

static int
qemuDomainRemoveDiskDevice()
...
    qemuDomainObjEnterMonitor(driver, vm);
    qemuMonitorDriveDel(priv->mon, drivestr);
    qemuDomainObjExitMonitor(driver, vm);
...

Yep, blast on through errors/failures

compared that to hostdev SCSI code:

static int
qemuDomainDetachHostSCSIDevice()
...
    if ((ret = qemuMonitorDelDevice(priv->mon, detach->info->alias)) == 0) {
        if ((ret = qemuMonitorDriveDel(priv->mon, drvstr)) < 0) {
            virErrorPtr orig_err = virSaveLastError();
            if (qemuMonitorAddDevice(priv->mon, devstr) < 0)
...


Ewww...  different.   More investigation turns up series of changes where adjustments were made to the detach paths VirtioDiskDevice, DiskDevice (SCSI/USB), ChrDevice, NetDevice, but not Host*Device... 

Lifting those "similar" changes into the Host path results in successful deletion.  Patches will be forthcoming after doing a bit more research to note where things were introduced, propagated, and fixed in other paths...

It's "interesting" that the host path does do much of the same processing of events, audits, and removal from the domain->hostdev list in a calling routine, but for some reason that DriveDel call never got moved.
Comment 2 John Ferlan 2014-09-24 13:12:20 UTC 
A patch series is now posted upstream for review

http://www.redhat.com/archives/libvir-list/2014-September/msg01456.html
Comment 5 lcheng 2014-10-17 11:38:44 UTC 
I can reproduce it in libvirt-1.2.8-4.el7.x86_64.

# rpm -q libvirt
libvirt-1.2.8-4.el7.x86_64

# virsh start b
Domain b started

# virsh dumpxml b | grep hostdev -A10
    <hostdev mode='subsystem' type='scsi' managed='no'>
      <source protocol='iscsi' name='iqn.yy:server.target1/1'>
        <host name='10.66.100.101' port='3260'/>
      </source>
      <alias name='hostdev0'/>
      <address type='drive' controller='0' bus='0' target='0' unit='0'/>
    </hostdev>
...

# cat hostdev.xml
    <hostdev mode='subsystem' type='scsi' managed='no'>
      <source protocol='iscsi' name='iqn.yy:server.target1/1'>
        <host name='10.66.100.101' port='3260'/>
      </source>
      <alias name='hostdev0'/>
      <address type='drive' controller='0' bus='0' target='0' unit='0'/>
    </hostdev>

# virsh detach-device b hostdev.xml
error: Failed to detach device from hostdev.xml
error: internal error: unable to execute QEMU command '__com.redhat_drive_del': An undefined error has occurred

============================================

But in latest libvirt-1.2.8-5.el7, it works:

1. On host:
# rpm -q libvirt
libvirt-1.2.8-5.el7.x86_64

# virsh start b
Domain b started

# virsh dumpxml b | grep hostdev -A10
    <hostdev mode='subsystem' type='scsi' managed='no'>
      <source protocol='iscsi' name='iqn.yy:server.target1/1'>
        <host name='10.66.100.101' port='3260'/>
      </source>
      <alias name='hostdev0'/>
      <address type='drive' controller='0' bus='0' target='0' unit='0'/>
    </hostdev>
...

# cat hostdev.xml
    <hostdev mode='subsystem' type='scsi' managed='no'>
      <source protocol='iscsi' name='iqn.yy:server.target1/1'>
        <host name='10.66.100.101' port='3260'/>
      </source>
      <alias name='hostdev0'/>
      <address type='drive' controller='0' bus='0' target='0' unit='0'/>
    </hostdev>


2. On guest check the device:
# fdisk -l
Disk /dev/sda: 4194 MB, 4194304000 bytes
255 heads, 63 sectors/track, 509 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disk identifier: 0x0002fd4f

   Device Boot      Start         End      Blocks   Id  System
/dev/sda1   *           1          64      512000   83  Linux
Partition 1 does not end on cylinder boundary.
/dev/sda2              64         510     3582976   8e  Linux LVM
Partition 2 does not end on cylinder boundary.

Disk /dev/sdb: 8591 MB, 8591507456 bytes
64 heads, 32 sectors/track, 8193 cylinders
Units = cylinders of 2048 * 512 = 1048576 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disk identifier: 0x000aaf3f

   Device Boot      Start         End      Blocks   Id  System
/dev/sdb1   *           2         501      512000   83  Linux
Partition 1 does not end on cylinder boundary.
/dev/sdb2             502        8193     7876608   8e  Linux LVM
Partition 2 does not end on cylinder boundary.

Disk /dev/mapper/VolGroup-lv_root: 3246 MB, 3246391296 bytes
255 heads, 63 sectors/track, 394 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disk identifier: 0x00000000

Disk /dev/mapper/VolGroup-lv_swap: 419 MB, 419430400 bytes
255 heads, 63 sectors/track, 50 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disk identifier: 0x00000000


3. On host detach the device.
# virsh detach-device b hostdev.xml
Device detached successfully


4. On guest check the device.
[root@localhost ~]# fdisk -l

Disk /dev/sda: 4194 MB, 4194304000 bytes
255 heads, 63 sectors/track, 509 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disk identifier: 0x0002fd4f

   Device Boot      Start         End      Blocks   Id  System
/dev/sda1   *           1          64      512000   83  Linux
Partition 1 does not end on cylinder boundary.
/dev/sda2              64         510     3582976   8e  Linux LVM
Partition 2 does not end on cylinder boundary.

Disk /dev/mapper/VolGroup-lv_root: 3246 MB, 3246391296 bytes
255 heads, 63 sectors/track, 394 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disk identifier: 0x00000000

Disk /dev/mapper/VolGroup-lv_swap: 419 MB, 419430400 bytes
255 heads, 63 sectors/track, 50 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disk identifier: 0x00000000



So change the status to VERIFIFD.
Comment 7 errata-xmlrpc 2015-03-05 07:44:33 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://rhn.redhat.com/errata/RHSA-2015-0323.html
Note You need to log in before you can comment on or make changes to this bug.