Bug 1503480

could reproduce in qemu-kvm-rhev-2.9.0-16.el7_4.10.x86_64

add keyword: regression because the failure to reproduce in 7.4.z:
kernel-3.10.0-693.5.1.el7.x86_64
qemu-kvm-rhev-2.9.0-16.el7_4.9.x86_64

Hi,

Could you try reproducing with the latest version?  There have been many dataplane fixes since this was originally reported, and there is a good chance that the bug has since been fixed.

Hi,
reproduced in 1/8 with the following components:
qemu-kvm-rhev-2.10.0-16.el7
kernel-3.10.0-830.el7.x86_64

debug info of dump file:
# gdb -q -c core.25173 
[New LWP 25175]
[New LWP 25177]
[New LWP 25179]
[New LWP 25184]
[New LWP 25183]
[New LWP 25178]
[New LWP 25186]
[New LWP 25182]
[New LWP 25181]
[New LWP 25185]
[New LWP 25174]
[New LWP 25193]
[New LWP 25187]
[New LWP 25188]
[New LWP 25190]
[New LWP 25173]
[New LWP 25192]
[New LWP 25189]
Reading symbols from /usr/libexec/qemu-kvm...Reading symbols from /usr/lib/debug/usr/libexec/qemu-kvm.debug...done.
done.

warning: .dynamic section for "/usr/lib64/libudev.so.1.6.2" is not at the expected address (wrong library or version mismatch?)

warning: Can't read pathname for load map: Input/output error.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/usr/libexec/qemu-kvm -name guest=test-virt0 -machine pc-i440fx-rhel7.4.0,accel'.
Program terminated with signal 6, Aborted.
#0  0x00007fcbc97431f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56	  return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb) bt
#0  0x00007fcbc97431f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007fcbc97448e8 in __GI_abort () at abort.c:90
#2  0x00007fcbc973c266 in __assert_fail_base (fmt=0x7fcbc988ee68 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x5616d2094722 "ctx->poll_disable_cnt == 0", file=file@entry=0x5616d20946d3 "util/aio-posix.c", line=line@entry=527, function=function@entry=0x5616d2094860 <__PRETTY_FUNCTION__.25907> "run_poll_handlers") at assert.c:92
#3  0x00007fcbc973c312 in __GI___assert_fail (assertion=assertion@entry=0x5616d2094722 "ctx->poll_disable_cnt == 0", file=file@entry=0x5616d20946d3 "util/aio-posix.c", line=line@entry=527, function=function@entry=0x5616d2094860 <__PRETTY_FUNCTION__.25907> "run_poll_handlers") at assert.c:101
#4  0x00005616d1fa6727 in aio_poll (max_ns=4000, ctx=0x5616d479fd40) at util/aio-posix.c:527
#5  0x00005616d1fa6727 in aio_poll (blocking=true, ctx=0x5616d479fd40) at util/aio-posix.c:562
#6  0x00005616d1fa6727 in aio_poll (ctx=0x5616d479fd40, blocking=blocking@entry=true)
    at util/aio-posix.c:602
#7  0x00005616d1d997c6 in iothread_run (opaque=0x5616d47733a0) at iothread.c:59
#8  0x00007fcbc9ad8e25 in start_thread (arg=0x7fcbb9237700) at pthread_create.c:308
#9  0x00007fcbc980634d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

This actually seems to be a problem with the AioContext polling mode and the locking around it. Stefan and Paolo should know this code.

This is the assertion that fails at the start of run_poll_handlers():

    assert(ctx->poll_disable_cnt == 0);

The caller of this function is try_poll_mode(), which only calls run_poll_handlers() if the assertion will hold true. So something must change the value in the short piece of code between the check and the call:

    if (blocking && ctx->poll_max_ns && ctx->poll_disable_cnt == 0) {
        /* See qemu_soonest_timeout() uint64_t hack */
        int64_t max_ns = MIN((uint64_t)aio_compute_timeout(ctx),
                             (uint64_t)ctx->poll_ns);

        if (max_ns) {
            poll_set_started(ctx, true);

            if (run_poll_handlers(ctx, max_ns)) {
                return true;
            }
        }
    }

This could be either something called by poll_set_started(), or possibly another thread if the locking isn't correct.

I'll just reassign the bug because I'd have to read and understand the whole polling mode related code first, while I assume Paolo already knows which interactions are possible at this point.

The assertion is wrong, it's valid for another thread to call aio_set_fd_handler at any time and change poll_disable_cnt.  I'll remove it and check on every iteration of run_poll_handlers.

Reproduced on qemu-kvm-rhev-2.12.0-15.el7.x86_64:

Core was generated by `/usr/libexec/qemu-kvm -S -name avocado-vt-vm1 -sandbox off -machine pc -nodefau'.
Program terminated with signal 11, Segmentation fault.
#0  aio_co_wake (co=0x0) at util/async.c:467
467	    ctx = atomic_read(&co->ctx);
Missing separate debuginfos, use: debuginfo-install mesa-libgbm-18.0.5-3.el7.x86_64
(gdb) bt
#0  0x0000560644a25bb3 in aio_co_wake (co=0x0) at util/async.c:467
#1  0x0000560644a27d88 in aio_dispatch_handlers (ctx=ctx@entry=0x560647e57900)
    at util/aio-posix.c:406
#2  0x0000560644a287fa in aio_poll (ctx=0x560647e57900, blocking=blocking@entry=true)
    at util/aio-posix.c:693
#3  0x00005606447f90fe in iothread_run (opaque=0x560647e75ce0) at iothread.c:64
#4  0x00007fbe80e96dd5 in start_thread (arg=0x7fbe78b45700) at pthread_create.c:307
#5  0x00007fbe80bbcead in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Tested with latest qemu package qemu-kvm-rhev-2.12.0-18.el7.x86_64, the assertion failure has been fixed, no core dump file generate.

But if shutdown the src guest after mirror, the src qemu still hang as comment 25 mentioned.

Hi Ademar,

The assertion issue has been fixed as Paolo mentioned, but the qmeu hang issue still existed.

And bz1525827 seems a dup of this one.

Do we need set this bug to 'VERIFIED' to track the assertion issue, and open a new bug to track the hang issue?


some trace log of src qemu:
futex(0x5628b4291d20, FUTEX_WAKE_PRIVATE, 1) = 0
sendmsg(51, {msg_name(0)=NULL, msg_iov(1)=[{"{\"timestamp\": {\"seconds\": 153801"..., 147}], msg_controllen=0, msg_flags=0}, 0) = 147
sendmsg(51, {msg_name(0)=NULL, msg_iov(1)=[{"{\"timestamp\": {\"seconds\": 153801"..., 147}], msg_controllen=0, msg_flags=0}, 0) = 147
sendmsg(51, {msg_name(0)=NULL, msg_iov(1)=[{"{\"timestamp\": {\"seconds\": 153801"..., 205}], msg_controllen=0, msg_flags=0}, 0) = 205
sendmsg(51, {msg_name(0)=NULL, msg_iov(1)=[{"{\"timestamp\": {\"seconds\": 153801"..., 149}], msg_controllen=0, msg_flags=0}, 0) = 149
sendmsg(51, {msg_name(0)=NULL, msg_iov(1)=[{"{\"timestamp\": {\"seconds\": 153801"..., 144}], msg_controllen=0, msg_flags=0}, 0) = 144
write(11, "\1\0\0\0\0\0\0\0", 8)        = 8
rt_sigprocmask(SIG_BLOCK, NULL, [BUS USR1 ALRM IO], 8) = 0
mmap(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f563dac1000
mprotect(0x7f563dac1000, 4096, PROT_NONE) = 0
rt_sigprocmask(SIG_SETMASK, [BUS USR1 ALRM IO], [BUS USR1 ALRM IO], 8) = 0
write(11, "\1\0\0\0\0\0\0\0", 8)        = 8
futex(0x5628b4291d20, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x5628b4291d20, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x5628b4291d20, FUTEX_WAKE_PRIVATE, 1) = 0
rt_sigprocmask(SIG_BLOCK, NULL, [BUS USR1 ALRM IO], 8) = 0
mmap(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f563d9c0000
mprotect(0x7f563d9c0000, 4096, PROT_NONE) = 0
rt_sigprocmask(SIG_SETMASK, [BUS USR1 ALRM IO], [BUS USR1 ALRM IO], 8) = 0
write(11, "\1\0\0\0\0\0\0\0", 8)        = 8
futex(0x5628b4291d20, FUTEX_WAKE_PRIVATE, 1) = 1
ppoll([{fd=8, events=POLLIN|POLLERR|POLLHUP}], 1, NULL, NULL, 8) = 1 ([{fd=8, revents=POLLIN}])
read(8, "\1\0\0\0\0\0\0\0", 512)        = 8
sendmsg(57, {msg_name(0)=NULL, msg_iov(1)=[{"%`\225\23\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 28}], msg_controllen=0, msg_flags=0}, 0) = 28
shutdown(57, SHUT_RDWR)                 = 0
futex(0x5628b4291d20, FUTEX_WAKE_PRIVATE, 1) = 1
ppoll([{fd=8, events=POLLIN|POLLERR|POLLHUP}], 1, NULL, NULL, 8


Thanks.

*** Bug 1525827 has been marked as a duplicate of this bug. ***

(In reply to CongLi from comment #28)
> Tested with latest qemu package qemu-kvm-rhev-2.12.0-18.el7.x86_64, the
> assertion failure has been fixed, no core dump file generate.
> 
> But if shutdown the src guest after mirror, the src qemu still hang as
> comment 25 mentioned.
> 
> Hi Ademar,
> 
> The assertion issue has been fixed as Paolo mentioned, but the qmeu hang
> issue still existed.
> 
> And bz1525827 seems a dup of this one.
> 

Done.

> Do we need set this bug to 'VERIFIED' to track the assertion issue, and open
> a new bug to track the hang issue?

Yes, let's do this to avoid confusion. Thanks.

Thanks Ademar.

Based on comment comment 25, comment 26, comment 28 and comment 30, set this bug to verified.

And will report a new bug for the hang issue with data plane.

Thanks.

(In reply to Ademar Reis from comment #30)
> (In reply to CongLi from comment #28)
> 
> > Do we need set this bug to 'VERIFIED' to track the assertion issue, and open
> > a new bug to track the hang issue?
> 
> Yes, let's do this to avoid confusion. Thanks.

Bug 1634219 will track the src qemu hang issue.

Thanks.