Bug 1329145

It is more easily reproduced on:
libvirt-1.3.3-3.fc25.x86_64
qemu-kvm-2.6.0-0.1.rc2.fc25.x86_64

(In reply to Han Han from comment #0)
> 2. Running following scripts to reproduce the bug:

Translating libvirt actions into QMP commands, we have:...

> #!/bin/bash -x
> DOM=ABRT
> OS_IMAGE=/var/lib/libvirt/images/V.qcow2
> WORK_DIR=/nfs/$DOM
> SCRIPT_DIR=`pwd`
> ABRT_STAMP=`date +%s`
> prep ()
> {
>     mkdir -p $WORK_DIR/{a..d}
>     if [ ! -f $WORK_DIR/a/a ]; then
>         cp $OS_IMAGE $WORK_DIR/a/a
>     fi
>     cd $WORK_DIR/b
>     qemu-img create -f qcow2 -o backing_file=../a/a,backing_fmt=qcow2 b
>     cd $WORK_DIR/c
>     qemu-img create -f qcow2 -o backing_file=../b/b,backing_fmt=qcow2 c
>     cd $WORK_DIR/d
>     qemu-img create -f qcow2 -o backing_file=../c/c,backing_fmt=qcow2 d
>     cd $SCRIPT_DIR

...create a backing chain (a/a <- b/b <- c/c <- d/d), where b/b, c/c, and d/d are all initially empty overlays of a/a, then

>     virsh define $DOM.xml && virsh start $DOM && sleep 30

...start the domain, presuming that d/d will be modified by the guest getting 30 seconds of runtime, then...

>     for i in {1..3};do
>         virsh -k0 blockcommit --active --verbose $DOM vda --shallow --pivot
> --keep-relative

iteration 1 commits d/d into c/c then makes c/c active,
iteration 2 commits c/c into b/b then makes b/b active,
iteration 3 commits b/b into a/a then makes a/a active.

The first iteration looks roughly like
{"execute":"block-commit",
 "arguments":{ "device":$name_of_vda,
 "top":"d/d", "base":"c/c" } }
to start the commit, then libvirt waits for completion by probing query-block-jobs but also waiting for events, until the job has reached ready state (that is, where 'offset' and 'len' have the same non-zero value), then calls block-job-complete to perform the pivot.

>     done
> }
> 
> cleanup ()
> {  
>     virsh destroy $DOM
>     virsh undefine $DOM --snapshots-metadata
>     rm $WORK_DIR/{b..d} -rf
> }   # ----------  end of function cleanup  ----------
> while true; do
>     prep
>     cleanup
> done
> 
> 3. When the script hang at Block commit: [100 %] , you can find
> qemu-kvm-rhev SIGABRT in abrt-cli
> # abrt-cli ls
> id 299764e1370d59ef9cac85382813d3e5e68963fa
> reason:         qemu-kvm killed by SIGABRT

It sounds like there may be some sort of race in qemu, perhaps where it is informing (whether via event or via a response to query-block-jobs) that the job appears to be complete, but where when libvirt then attempts block-job-complete it causes a race because the job was not actually complete, and that this is triggering an assertion in qemu.  But I'm not sure on how to better debug the issue, so much as being available to offer assistance in trying to reproduce the problem using just qemu without libvirt in the mix.

(In reply to Eric Blake from comment #3)
> (In reply to Han Han from comment #0)
> > 2. Running following scripts to reproduce the bug:
> 
> Translating libvirt actions into QMP commands, we have:...
> 
> > #!/bin/bash -x
> > DOM=ABRT
> > OS_IMAGE=/var/lib/libvirt/images/V.qcow2
> > WORK_DIR=/nfs/$DOM
> > SCRIPT_DIR=`pwd`
> > ABRT_STAMP=`date +%s`
> > prep ()
> > {
> >     mkdir -p $WORK_DIR/{a..d}
> >     if [ ! -f $WORK_DIR/a/a ]; then
> >         cp $OS_IMAGE $WORK_DIR/a/a
> >     fi
> >     cd $WORK_DIR/b
> >     qemu-img create -f qcow2 -o backing_file=../a/a,backing_fmt=qcow2 b
> >     cd $WORK_DIR/c
> >     qemu-img create -f qcow2 -o backing_file=../b/b,backing_fmt=qcow2 c
> >     cd $WORK_DIR/d
> >     qemu-img create -f qcow2 -o backing_file=../c/c,backing_fmt=qcow2 d
> >     cd $SCRIPT_DIR
> 
> ...create a backing chain (a/a <- b/b <- c/c <- d/d), where b/b, c/c, and
> d/d are all initially empty overlays of a/a, then
> 
> >     virsh define $DOM.xml && virsh start $DOM && sleep 30
> 
> ...start the domain, presuming that d/d will be modified by the guest
> getting 30 seconds of runtime, then...
> 
> >     for i in {1..3};do
> >         virsh -k0 blockcommit --active --verbose $DOM vda --shallow --pivot
> > --keep-relative
> 
> iteration 1 commits d/d into c/c then makes c/c active,
> iteration 2 commits c/c into b/b then makes b/b active,
> iteration 3 commits b/b into a/a then makes a/a active.
> 
> The first iteration looks roughly like
> {"execute":"block-commit",
>  "arguments":{ "device":$name_of_vda,
>  "top":"d/d", "base":"c/c" } }
> to start the commit, then libvirt waits for completion by probing
> query-block-jobs but also waiting for events, until the job has reached
> ready state (that is, where 'offset' and 'len' have the same non-zero
> value), then calls block-job-complete to perform the pivot.
> 

Er, libvirt uses len == offset to determine 'READY' instead of waiting for the QMP event? ...

That makes me sorta nervous.

> >     done
> > }
> > 
> > cleanup ()
> > {  
> >     virsh destroy $DOM
> >     virsh undefine $DOM --snapshots-metadata
> >     rm $WORK_DIR/{b..d} -rf
> > }   # ----------  end of function cleanup  ----------
> > while true; do
> >     prep
> >     cleanup
> > done
> > 
> > 3. When the script hang at Block commit: [100 %] , you can find
> > qemu-kvm-rhev SIGABRT in abrt-cli
> > # abrt-cli ls
> > id 299764e1370d59ef9cac85382813d3e5e68963fa
> > reason:         qemu-kvm killed by SIGABRT
> 
> It sounds like there may be some sort of race in qemu, perhaps where it is
> informing (whether via event or via a response to query-block-jobs) that the
> job appears to be complete, but where when libvirt then attempts
> block-job-complete it causes a race because the job was not actually
> complete, and that this is triggering an assertion in qemu.  But I'm not

Yeah, looks like pending requests exist at the time we invoke bdrv_replace_in_backing_chain, and we fail assert(!bdrv_requests_pending(old)):

#3  0x00007fd48092d612 in __GI___assert_fail (assertion=assertion@entry=0x7fd49aa58817 "!bdrv_requests_pending(old)", file=file@entry=0x7fd49aa1f11a "block.c", line=line@entry=2092, 
    function=function@entry=0x7fd49aa599b0 <__PRETTY_FUNCTION__.35035> "bdrv_replace_in_backing_chain") at assert.c:101

> sure on how to better debug the issue, so much as being available to offer
> assistance in trying to reproduce the problem using just qemu without
> libvirt in the mix.



Han: 

You know, the code surrounding the draining of requests has changed from 2.6.0 to 2.7.0 a good deal... Han, could I be very, very obnoxious and ask you to re-test using a 2.7.0 package from fedora?

Either of these two should do it: qemu-2.7.0-0.2.rc3.fc25 qemu-2.7.0-0.2.rc3.fc26

I will work on reproducing myself tomorrow, otherwise.

Thank you,
--js

Hi John, 
I ran the script for thousands of loops on libvirt-2.2.0-1.fc26.x86_64 qemu-2.7.0-0.2.rc3.fc26.x86_64 , the bug was not reproduced.

(In reply to Han Han from comment #5)
> Hi John, 
> I ran the script for thousands of loops on libvirt-2.2.0-1.fc26.x86_64
> qemu-2.7.0-0.2.rc3.fc26.x86_64 , the bug was not reproduced.

Great, thanks!

I spent some time trying to reproduce this for 2.6.0, but couldn't. As such, I'm not readily able to pick out which commit in the 2.6.0 -> 2.7.0 timeframe may have fixed the issue for you.

This isn't marked a blocker or regression; at this point I need to postpone this to 7.4 unless there is a very compelling reason otherwise. It's not clear to me which commit specifically may have changed the locking/draining behavior, so I was hoping to do a git bisect.

However, I can't reproduce; and I assume it's not a great use of QE's time to try to bisect for me.

So for now, I'm going to shuffle this to 7.4.0 and I will return to it shortly.

Since we rebased, this is likely fixed for us as we couldn't reproduce in 2.7. We'll collect the apparent fix in the new version.

(I think POST is correct in this case.)

Set Verified per comment5 and comment7. If you still hit the issue please feel free to reopen.

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/RHSA-2017:2392

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/RHSA-2017:2392

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/RHSA-2017:2392

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/RHSA-2017:2392

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/RHSA-2017:2392

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/RHSA-2017:2392