1134294 – libvirt can't acquire state change lock after do blockjob --pivot before block copy job is finished

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 1134294 - libvirt can't acquire state change lock after do blockjob --pivot before block copy job is finished

Summary: libvirt can't acquire state change lock after do blockjob --pivot before bloc...

Keywords:
Status:	CLOSED DUPLICATE of bug 1139567
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	libvirt
Sub Component:
Version:	7.1
Hardware:	Unspecified
OS:	Unspecified
Priority:	medium
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	Eric Blake
QA Contact:	Virtualization Bugs
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2014-08-27 09:03 UTC by Shanzhi Yu
Modified:	2015-01-28 05:42 UTC (History)
CC List:	9 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2015-01-14 04:59:16 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Description Shanzhi Yu 2014-08-27 09:03:32 UTC

Description of problem:

libvirt can't acquire state change lock after do blockjob --pivot before block copy job is finished


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


How reproducible:

100%

Steps to Reproduce:

1.Prepare a transient guest

# virsh list --transient
 Id    Name                           State
----------------------------------------------------
 2     rhel6                          running

2.Do blockcopy without --pivot in first terminal

# virsh blockcopy rhel6 vda /var/lib/libvirt/copy.img
Block Copy started

3.Before block copy job is finished, do blockjob --pivot in second terminal

# virsh blockjob rhel6 vda --info ;virsh blockjob rhel6 vda --pivot ;
Block Copy: [ 31 %]


4.Check blockjob info in first terminal
# virsh blockjob rhel6 vda --info
error: Timed out during operation: cannot acquire state change lock

# virsh blockjob rhel6 vda --abort
error: Timed out during operation: cannot acquire state change lock


Actual results:

Guest will keep having one block job and can't do any block job related operations

Expected results:

In step 3, libvirt should post error like "error: can't do pivot: domain still in block copy job"


Additional info:

This can be reproduced on RHEL6.6

Comment 1 Osier Yang 2014-09-13 03:51:51 UTC

Hi, Shanzhi

The bug is not always reproduceable, am I right? I got the similar problem (2 times) when long running our test cases in 2 days.

The command I used is:

# virsh blockcopy $domain $head_disk $snapshot_img --shallow --reuse-external --wait --pivot

When the problem occurred, all the blockjob command fails with "can't acquire lock", since the lock is held forever.  There is no way to recover except restarting libvirtd.

Regards,
Osier

Comment 2 Osier Yang 2014-09-13 04:03:17 UTC

Forgot to mention, I used libvirt-1.2.7 too. 

And when the hanging problem happened, the mirroring phase of "blockcopy" was actually finished.

Comment 3 Shanzhi Yu 2014-09-14 15:43:13 UTC

(In reply to Osier Yang from comment #1)
> Hi, Shanzhi
> 
> The bug is not always reproduceable, am I right? I got the similar problem
> (2 times) when long running our test cases in 2 days.
> 
> The command I used is:
> 
> # virsh blockcopy $domain $head_disk $snapshot_img --shallow
> --reuse-external --wait --pivot
> 
> When the problem occurred, all the blockjob command fails with "can't
> acquire lock", since the lock is held forever.  There is no way to recover
> except restarting libvirtd.
> 
> Regards,
> Osier

Hi Osier,

Thanks for your info. 
Actually I can reproduce it 100 percents. There is a little difference between my steps and yours. My steps is for negative test. Do pivot before copy is ready.
I will try to reproduce it by your steps. 

To comment 2,
When the hanging problem happened, I found the copy job(first phase of 'blockcopy') still be running in backgrand.

Thanks again.

Comment 4 Shanzhi Yu 2014-09-15 03:27:17 UTC

I met another error after try many times. QEMU command 'block-job-complete' can not be completed.


1. Set log_level=1,log_outputs="1:file:/tmp/libvirtd.log" in libvirtd.conf
# grep -v "^#" /etc/libvirt/libvirtd.conf
log_level=1
log_outputs="1:file:/tmp/libvirtd.log"

2. Do blockcopy in one terminal

# for i in `seq 1 100`;do virsh blockcopy rh7 vda /var/lib/libvirt/images/copy-$i.img --verbose --wait --pivot --shallow ;done
Block Copy: [100 %]
Successfully pivoted
Block Copy: [100 %]
Successfully pivoted
Block Copy: [100 %]
Successfully pivoted
Block Copy: [100 %]
Successfully pivoted
Block Copy: [100 %]


3. Check error in another terminal

# tailf /tmp/libvirtd.log |grep error
2014-09-15 03:04:39.677+0000: 2115: debug : qemuMonitorIOProcess:399 : QEMU_MONITOR_IO_PROCESS: mon=0x7f1d0000bbc0 buf={"id": "libvirt-228", "error": {"class": "GenericError", "desc": "The active block job for device 'drive-virtio-disk0' cannot be completed"}}
2014-09-15 03:04:39.677+0000: 2115: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"id": "libvirt-228", "error": {"class": "GenericError", "desc": "The active block job for device 'drive-virtio-disk0' cannot be completed"}}]
2014-09-15 03:04:39.677+0000: 2115: debug : virJSONValueFromString:1136 : string={"id": "libvirt-228", "error": {"class": "GenericError", "desc": "The active block job for device 'drive-virtio-disk0' cannot be completed"}}
2014-09-15 03:04:39.677+0000: 2115: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7f1d0000bbc0 reply={"id": "libvirt-228", "error": {"class": "GenericError", "desc": "The active block job for device 'drive-virtio-disk0' cannot be completed"}}
2014-09-15 03:04:39.678+0000: 2120: debug : virJSONValueToString:1303 : result={"id":"libvirt-228","error":{"class":"GenericError","desc":"The active block job for device 'drive-virtio-disk0' cannot be completed"}}
2014-09-15 03:04:39.678+0000: 2120: debug : qemuMonitorJSONCheckError:366 : unable to execute QEMU command {"execute":"block-job-complete","arguments":{"device":"drive-virtio-disk0"},"id":"libvirt-228"}: {"id":"libvirt-228","error":{"class":"GenericError","desc":"The active block job for device 'drive-virtio-disk0' cannot be completed"}}
2014-09-15 03:04:39.678+0000: 2120: error : qemuMonitorJSONCheckError:377 : internal error: unable to execute QEMU command 'block-job-complete': The active block job for device 'drive-virtio-disk0' cannot be completed

4. Check guest xml 

# virsh dumpxml rh7
 <disk type='file' device='disk'>
      <driver type='qcow2' cache='none'/>
      <source file='/var/lib/libvirt/images/copy-4.img'/>
      <backingStore type='block' index='1'>
        <format type='raw'/>
        <source dev='/dev/sda7'/>
        <backingStore/>
      </backingStore>
      <target dev='vda' bus='virtio'/>
      <alias name='virtio-disk0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x06' function='0x0'/>
    </disk>

5. When try to get blockjob information, will met can't acquire state change lock 

# virsh blockjob rh7 vda 
error: Timed out during operation: cannot acquire state change lock

More like another bug ? 
Eirc, Can you help confirm this?

Thanks

Comment 5 Osier Yang 2014-09-15 08:05:11 UTC

(In reply to Shanzhi Yu from comment #4)
> I met another error after try many times. QEMU command 'block-job-complete'
> can not be completed.
> 
> 
> 1. Set log_level=1,log_outputs="1:file:/tmp/libvirtd.log" in libvirtd.conf
> # grep -v "^#" /etc/libvirt/libvirtd.conf
> log_level=1
> log_outputs="1:file:/tmp/libvirtd.log"
> 
> 2. Do blockcopy in one terminal
> 
> # for i in `seq 1 100`;do virsh blockcopy rh7 vda
> /var/lib/libvirt/images/copy-$i.img --verbose --wait --pivot --shallow ;done
> Block Copy: [100 %]
> Successfully pivoted
> Block Copy: [100 %]
> Successfully pivoted
> Block Copy: [100 %]
> Successfully pivoted
> Block Copy: [100 %]
> Successfully pivoted
> Block Copy: [100 %]
> 
> 
> 3. Check error in another terminal
> 
> # tailf /tmp/libvirtd.log |grep error
> 2014-09-15 03:04:39.677+0000: 2115: debug : qemuMonitorIOProcess:399 :
> QEMU_MONITOR_IO_PROCESS: mon=0x7f1d0000bbc0 buf={"id": "libvirt-228",
> "error": {"class": "GenericError", "desc": "The active block job for device
> 'drive-virtio-disk0' cannot be completed"}}
> 2014-09-15 03:04:39.677+0000: 2115: debug : qemuMonitorJSONIOProcessLine:179
> : Line [{"id": "libvirt-228", "error": {"class": "GenericError", "desc":
> "The active block job for device 'drive-virtio-disk0' cannot be completed"}}]
> 2014-09-15 03:04:39.677+0000: 2115: debug : virJSONValueFromString:1136 :
> string={"id": "libvirt-228", "error": {"class": "GenericError", "desc": "The
> active block job for device 'drive-virtio-disk0' cannot be completed"}}
> 2014-09-15 03:04:39.677+0000: 2115: debug : qemuMonitorJSONIOProcessLine:199
> : QEMU_MONITOR_RECV_REPLY: mon=0x7f1d0000bbc0 reply={"id": "libvirt-228",
> "error": {"class": "GenericError", "desc": "The active block job for device
> 'drive-virtio-disk0' cannot be completed"}}
> 2014-09-15 03:04:39.678+0000: 2120: debug : virJSONValueToString:1303 :
> result={"id":"libvirt-228","error":{"class":"GenericError","desc":"The
> active block job for device 'drive-virtio-disk0' cannot be completed"}}
> 2014-09-15 03:04:39.678+0000: 2120: debug : qemuMonitorJSONCheckError:366 :
> unable to execute QEMU command
> {"execute":"block-job-complete","arguments":{"device":"drive-virtio-disk0"},
> "id":"libvirt-228"}:
> {"id":"libvirt-228","error":{"class":"GenericError","desc":"The active block
> job for device 'drive-virtio-disk0' cannot be completed"}}
> 2014-09-15 03:04:39.678+0000: 2120: error : qemuMonitorJSONCheckError:377 :
> internal error: unable to execute QEMU command 'block-job-complete': The
> active block job for device 'drive-virtio-disk0' cannot be completed
> 

Thanks for the testing, Shanzhi.

These errors tells the bug is in QEMU.

Comment 6 Shanzhi Yu 2014-09-16 16:13:53 UTC

There is a qemu-kvm-rhev bug 1130489 should cause problem in comment 4

Comment 7 Eric Blake 2015-01-13 20:06:41 UTC

Upstream is reporting the same symptoms:
https://www.redhat.com/archives/libvir-list/2015-January/msg00454.html

Comment 8 Eric Blake 2015-01-14 04:59:16 UTC

After more investigation, it looks like this problem was solved by the same patch as for bug 1139567

*** This bug has been marked as a duplicate of bug 1139567 ***

Comment 9 Shanzhi Yu 2015-01-28 05:42:47 UTC

After bug 1139567 be fixed then retest this bug, it work fine.
Do pivot before copy is not finish will met error like below:

# virsh blockjob test vda --pivot 
error: block copy still active: disk 'vda' not ready for pivot yet

# virsh blockjob test vda 
Block Copy: [ 40 %]

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