Red Hat Bugzilla – Bug 1141732
wrong QMP argument 'id' when detaching iscsi hostdev
Last modified: 2015-03-05 02:44:33 EST
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.
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@192.168.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@192.168.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@192.168.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@192.168.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@192.168.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@192.168.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.
A patch series is now posted upstream for review http://www.redhat.com/archives/libvir-list/2014-September/msg01456.html
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.
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