Bug 1452045
Summary: | qemuDomainGetBlockInfo get error when execute domblkinfo and blockcommit in parallel for block device | ||||||
---|---|---|---|---|---|---|---|
Product: | Red Hat Enterprise Linux 7 | Reporter: | Yanqiu Zhang <yanqzhan> | ||||
Component: | libvirt | Assignee: | Peter Krempa <pkrempa> | ||||
Status: | CLOSED ERRATA | QA Contact: | Han Han <hhan> | ||||
Severity: | urgent | Docs Contact: | |||||
Priority: | unspecified | ||||||
Version: | 7.4 | CC: | dyuan, hhan, lmen, mzhan, pkrempa, rbalakri, xuzhang, yanqzhan | ||||
Target Milestone: | rc | Keywords: | Regression, TestBlocker | ||||
Target Release: | --- | ||||||
Hardware: | x86_64 | ||||||
OS: | Linux | ||||||
Whiteboard: | |||||||
Fixed In Version: | libvirt-3.2.0-9.el7 | Doc Type: | If docs needed, set a value | ||||
Doc Text: | Story Points: | --- | |||||
Clone Of: | Environment: | ||||||
Last Closed: | 2017-08-02 00:08:25 UTC | Type: | Bug | ||||
Regression: | --- | Mount Type: | --- | ||||
Documentation: | --- | CRM: | |||||
Verified Versions: | Category: | --- | |||||
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
Cloudforms Team: | --- | Target Upstream Version: | |||||
Embargoed: | |||||||
Bug Depends On: | |||||||
Bug Blocks: | 1449577, 1456511 | ||||||
Attachments: |
|
Description
Yanqiu Zhang
2017-05-18 08:41:05 UTC
(In reply to yanqzhan from comment #0) [...] > 2.In step6, sometimes will fail to delete the snapshot with following error, > the probability is above 50%. > "May 18, 2017 1:55:01 PM Failed to delete snapshot 'yan-V2-snap' for VM > 'yan-V2'." > "May 18, 2017 1:50:57 PM VDSM hostB command MergeVDS failed: Drive image > file could not be found" What is the libvirt error in this case? > Expected results > Should not get error in step3 terminal, and should not block snapshot > deleting for rhevm product with iscsi storage. So these seem like two separate issues, but first we need to clarify what is the cause for the failure of snapshot deletion. I'd like to know which libvirt APIs are called and what is the error. Created attachment 1279933 [details]
libvirt-testing-libvirtd.log
(In reply to Peter Krempa from comment #3) > (In reply to yanqzhan from comment #0) > > [...] > > > 2.In step6, sometimes will fail to delete the snapshot with following error, > > the probability is above 50%. > > "May 18, 2017 1:55:01 PM Failed to delete snapshot 'yan-V2-snap' for VM > > 'yan-V2'." > > "May 18, 2017 1:50:57 PM VDSM hostB command MergeVDS failed: Drive image > > file could not be found" > > What is the libvirt error in this case? > Please refer to Additional info 2, the libvirt error is: if ret is None: raise libvirtError ('virDomainGetBlockInfo() failed', dom=self) libvirtError: internal error: failed to query the maximum written offset of block device 'vdb' > > Expected results > > Should not get error in step3 terminal, and should not block snapshot > > deleting for rhevm product with iscsi storage. > > So these seem like two separate issues, but first we need to clarify what is > the cause for the failure of snapshot deletion. > > I'd like to know which libvirt APIs are called and what is the error. The API is virDomainGetBlockInfo(). And to reproduce the error in libvirt way is step1-5. So this is the sequence of events, obtained from the logs (and trimmed) by: egrep '(QEMU_MONITOR_IO_WRITE|error|BLOCK|Commit)' 1452045-libvirtd.log 2017-05-18 08:53:56.128+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-blockstats","id":"libvirt-373"} 2017-05-18 08:53:56.131+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-block","id":"libvirt-374"} 2017-05-18 08:53:56.176+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-blockstats","id":"libvirt-375"} 2017-05-18 08:53:56.180+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-block","id":"libvirt-376"} qemuDomainGetBlockInfo works properly 2017-05-18 08:53:56.189+0000: 13488: debug : virThreadJobSet:96 : Thread 13488 (virNetServerHandleJob) is now running job remoteDispatchDomainBlockCommit 2017-05-18 08:53:56.189+0000: 13488: debug : remoteDispatchDomainBlockCommitHelper:3545 : server=0x557e1c588a90 client=0x557e1c5be580 msg=0x557e1c5be770 rerr=0x7f08d3ee0c00 args=0x7f08bc002020 ret=0x7f08bc000bb0 2017-05-18 08:53:56.189+0000: 13488: debug : virDomainBlockCommit:10203 : dom=0x7f08bc0020f0, (VM: name=V, uuid=c3a57d2a-7d75-493a-a699-786ac2fd54b3), disk=vda, base=<null>, top=<null>, bandwidth=0, flags=5 2017-05-18 08:53:56.221+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-block","id":"libvirt-377"} 2017-05-18 08:53:56.224+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-block","id":"libvirt-378"} 2017-05-18 08:53:56.227+0000: 13488: debug : qemuMonitorBlockCommit:3321 : device=drive-virtio-disk0, top=/dev/sdd, base=/var/lib/libvirt/images/V.qcow2, backingName=<null>, bandwidth=0 2017-05-18 08:53:56.227+0000: 13488: debug : qemuMonitorBlockCommit:3323 : mon:0x7f0868000fb0 vm:0x7f08742b8950 json:1 fd:23 2017-05-18 08:53:56.228+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"block-commit","arguments":{"device":"drive-virtio-disk0","top":"/dev/sdd","base":"/var/lib/libvirt/images/V.qcow2"},"id":"libvirt-379"} Active layer block commit operation is started 2017-05-18 08:53:56.232+0000: 13484: info : qemuMonitorIOProcess:431 : QEMU_MONITOR_IO_PROCESS: mon=0x7f0868000fb0 buf={"timestamp": {"seconds": 1495097636, "microseconds": 232749}, "event": "BLOCK_JOB_READY", "data": {"device": "drive-virtio-disk0", "len": 0, "offset": 0, "speed": 0, "type": "commit"}} 2017-05-18 08:53:56.232+0000: 13484: debug : qemuMonitorJSONIOProcessLine:193 : Line [{"timestamp": {"seconds": 1495097636, "microseconds": 232749}, "event": "BLOCK_JOB_READY", "data": {"device": "drive-virtio-disk0", "len": 0, "offset": 0, "speed": 0, "type": "commit"}}] 2017-05-18 08:53:56.232+0000: 13484: debug : virJSONValueFromString:1713 : string={"timestamp": {"seconds": 1495097636, "microseconds": 232749}, "event": "BLOCK_JOB_READY", "data": {"device": "drive-virtio-disk0", "len": 0, "offset": 0, "speed": 0, "type": "commit"}} 2017-05-18 08:53:56.233+0000: 13484: info : qemuMonitorJSONIOProcessLine:208 : QEMU_MONITOR_RECV_EVENT: mon=0x7f0868000fb0 event={"timestamp": {"seconds": 1495097636, "microseconds": 232749}, "event": "BLOCK_JOB_READY", "data": {"device": "drive-virtio-disk0", "len": 0, "offset": 0, "speed": 0, "type": "commit"}} 2017-05-18 08:53:56.233+0000: 13484: debug : qemuMonitorEmitEvent:1297 : mon=0x7f0868000fb0 event=BLOCK_JOB_READY 2017-05-18 08:53:56.233+0000: 13484: debug : qemuMonitorJSONIOProcessEvent:179 : handle BLOCK_JOB_READY handler=0x7f088fef1b60 data=0x557e1c5773d0 Block commit finihed, the job is ready to be merged. 2017-05-18 08:53:56.234+0000: 13488: debug : virThreadJobClear:121 : Thread 13488 (virNetServerHandleJob) finished job remoteDispatchDomainBlockCommit with ret=0 virDomainBlockCommit api returns success. 2017-05-18 08:53:56.236+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-blockstats","id":"libvirt-380"} 2017-05-18 08:53:56.240+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-block","id":"libvirt-381"} 2017-05-18 08:53:56.243+0000: 13489: error : qemuDomainGetBlockInfo:11550 : internal error: failed to query the maximum written offset of block device 'vda' qemuDomainGetBlockInfo fails at this point 2017-05-18 08:53:56.244+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-block-jobs","id":"libvirt-382"} 2017-05-18 08:53:56.249+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"block-job-complete","arguments":{"device":"drive-virtio-disk0"},"id":"libvirt-383"} Request to pivot to the backing image 2017-05-18 08:53:56.250+0000: 13484: info : qemuMonitorIOProcess:431 : QEMU_MONITOR_IO_PROCESS: mon=0x7f0868000fb0 buf={"timestamp": {"seconds": 1495097636, "microseconds": 250756}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "drive-virtio-disk0", "len": 0, "offset": 0, "speed": 0, "type": "commit"}} 2017-05-18 08:53:56.250+0000: 13484: debug : qemuMonitorJSONIOProcessLine:193 : Line [{"timestamp": {"seconds": 1495097636, "microseconds": 250756}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "drive-virtio-disk0", "len": 0, "offset": 0, "speed": 0, "type": "commit"}}] 2017-05-18 08:53:56.251+0000: 13484: debug : virJSONValueFromString:1713 : string={"timestamp": {"seconds": 1495097636, "microseconds": 250756}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "drive-virtio-disk0", "len": 0, "offset": 0, "speed": 0, "type": "commit"}} 2017-05-18 08:53:56.251+0000: 13484: info : qemuMonitorJSONIOProcessLine:208 : QEMU_MONITOR_RECV_EVENT: mon=0x7f0868000fb0 event={"timestamp": {"seconds": 1495097636, "microseconds": 250756}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "drive-virtio-disk0", "len": 0, "offset": 0, "speed": 0, "type": "commit"}} 2017-05-18 08:53:56.251+0000: 13484: debug : qemuMonitorEmitEvent:1297 : mon=0x7f0868000fb0 event=BLOCK_JOB_COMPLETED 2017-05-18 08:53:56.251+0000: 13484: debug : qemuMonitorJSONIOProcessEvent:179 : handle BLOCK_JOB_COMPLETED handler=0x7f088fef1bc0 data=0x557e1c5789d0 Pivot is finished successfully, events are dispatched. 2017-05-18 08:53:56.268+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-block","id":"libvirt-384"} 2017-05-18 08:53:56.271+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-named-block-nodes","id":"libvirt-385"} 2017-05-18 08:53:56.342+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-blockstats","id":"libvirt-386"} 2017-05-18 08:53:56.345+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-block","id":"libvirt-387"} 2017-05-18 08:53:56.389+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-blockstats","id":"libvirt-388"} 2017-05-18 08:53:56.392+0000: 13484: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f0868000fb0 buf={"execute":"query-block","id":"libvirt-389"} qemuDomainGetBlockInfo works properly again commit c245f558369de5eb404e54728bf69ad27942e912 Author: Peter Krempa <pkrempa> Date: Mon May 22 17:44:00 2017 +0200 qemu: Don't error out if allocation info can't be queried qemuDomainGetBlockInfo would error out if qemu did not report 'wr_highest_offset'. This usually does not happen, but can happen briefly during active layer block commit. There's no need to report the error, we can simply report that the disk is fully alocated at that point. Verify it on libvirt-3.2.0-9.virtcov.el7.x86_64 qemu-kvm-rhev-2.9.0-8.el7.x86_64 Using following script to get blkinfo while blockcommit, blockpull, blockcopy: 1. Prepare a VM xml with following disk: <disk type='file' device='disk'> <driver name='qemu' type='qcow2'/> <source file='/var/lib/libvirt/images/V.qcow2'/> <backingStore/> <target dev='vda' bus='virtio'/> <alias name='virtio-disk0'/> <address type='pci' domain='0x0000' bus='0x00' slot='0x07' function='0x0'/> </disk> 2. Prepare block sdb with partition sdb1,sdb2 # lsblk /dev/sdb NAME MAJ:MIN RM SIZE RO TYPE MOUNTPOINT sdb 8:16 0 30G 0 disk ├─sdb1 8:17 0 15G 0 part ├─sdb2 8:18 0 15G 0 part 3. Run following scripts to get blkinfo while blockcommit, blockpull, blockcopy: #!/bin/bash DOM=V SNAP=/dev/sdb echo '' > /var/log/libvirt/libvirtd.log echo '' > /var/log/libvirt/qemu/$DOM.log set -x virsh create $DOM.xml && sleep 10 virsh snapshot-create-as $DOM --disk-only --diskspec vda,file=/dev/sdb1 --no-metadata set +x while true; do virsh domblkinfo $DOM vda 1>/dev/null;done& set -x virsh blockcommit $DOM vda --active --shallow --wait --verbose --pivot --async virsh blockpull $DOM vda --wait --verbose --async virsh blockcopy $DOM vda /dev/sdb2 --blockdev --wait --verbose --async --pivot sleep 2 kill %1 virsh destroy $DOM grep 'error' /var/log/libvirt/libvirtd.log /var/log/libvirt/qemu/$DOM.log >> result The result: + virsh create V.xml Domain V created from V.xml + sleep 10 + virsh snapshot-create-as V --disk-only --diskspec vda,file=/dev/sdb1 --no-metadata Domain snapshot 1496887939 created + set +x + virsh blockcommit V vda --active --shallow --wait --verbose --pivot --async Block commit: [100 %] Successfully pivoted + virsh blockpull V vda --wait --verbose --async Block Pull: [100 %] Pull complete + virsh blockcopy V vda /dev/sdb2 --blockdev --wait --verbose --async --pivot Block Copy: [100 %] Successfully pivoted + sleep 2 + kill %1 + virsh destroy V Domain V destroyed ./1452045.sh: line 36: 6768 Terminated while true; do virsh domblkinfo $DOM vda > /dev/null; done No error found in result file. Bug fixed. 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/RHEA-2017:1846 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/RHEA-2017:1846 |