Bug 918798

Dafna,  the vm is reported as Down by vdsm after the connection was lost with the qemu process and then engine sends the destory.

libvirtEventLoop::DEBUG::2013-03-06 11:00:20,028::vm::1047::vm.Vm::(setDownStatus) vmId=`53c25ad5-184e-49fe-b3d9-09b46db4d4df`::Changed state to Down: Lost connection with qemu process

Thread-46827::DEBUG::2013-03-06 11:00:21,342::BindingXMLRPC::913::vds::(wrapper) client [10.35.161.49]::call vmGetStats with ('53c25ad5-184e-49fe-b3d9-09b46db4d4df',) {}
Thread-46827::DEBUG::2013-03-06 11:00:21,342::BindingXMLRPC::920::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': '
Down', 'hash': '-6607417337149127009', 'exitMessage': 'Lost connection with qemu process', 'vmId': '53c25ad5-184e-49fe-b3d9-09b46db4d4df', 'timeOffset': '-43200', 'exitCode'
: 1}]}

Thread-46828::DEBUG::2013-03-06 11:00:21,370::libvirtvm::2588::vm.Vm::(destroy) vmId=`53c25ad5-184e-49fe-b3d9-09b46db4d4df`::destroy Called


can you elaborate if there's an issue here?

there was no issue - reproduction was as written in the steps. 
please talk to vdsm, kvm or libvirt people if you think this issue is not related to engine component.

Dafna,  please attach all the other relevant logs (libvirt/qemu process) so it's possible to see what happend to the vm and why it went down - if you can please also update the header to the current bug as the sent destory is not a bug.

I just got the same issue when live migrating a preallocated disk twice. 
attaching the logs from it.

Created attachment 708912 [details]
logs

Federico, please take a look - vdsm reports that the vm is down.

Yes the qemu process crashed for some reason. There's no trace of the reason on Dafna's host but I have been able to reproduce the issue looping a pause/hot(un)plug/resume:

while true; do
  virsh suspend vm1
  virsh attach-disk vm1 /tmp/hotplug-disk.qcow vdb
  sleep 5
  virsh resume vm1
  sleep 5
  virsh suspend vm1
  virsh detach-disk vm1 /tmp/hotplug-disk.qcow vdb
  sleep 5
  virsh resume vm1
  sleep 5
done

After a while the qemu process crashed with:

Program received signal SIGSEGV, Segmentation fault.
qemu_bh_delete (bh=0x0) at async.c:119
119	    bh->scheduled = 0;

#0  qemu_bh_delete (bh=0x0) at async.c:119
#1  0x00007f0917b3fe80 in virtio_blk_dma_restart_bh (opaque=0x7f0919136c00) at /usr/src/debug/qemu-kvm-1.2.0/hw/virtio-blk.c:440
#2  0x00007f0917971026 in qemu_bh_poll () at async.c:71
#3  0x00007f0917a8e7f3 in main_loop_wait (nonblocking=<optimized out>) at main-loop.c:506
#4  0x00007f091796ad63 in main_loop () at /usr/src/debug/qemu-kvm-1.2.0/vl.c:1643
#5  main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>) at /usr/src/debug/qemu-kvm-1.2.0/vl.c:3792

# rpm -q qemu libvirt
qemu-1.2.2-6.fc18.x86_64
libvirt-0.10.2.3-1.fc18.x86_64

We don't have any real proof that it's exactly the same issue even though I feel that there's an high chance that it is.
Qemu probably needs to fix this anyway.

(In reply to comment #8)
> Yes the qemu process crashed for some reason. There's no trace of the reason
> on Dafna's host but I have been able to reproduce the issue looping a
> pause/hot(un)plug/resume:
> 
> while true; do
>   virsh suspend vm1
>   virsh attach-disk vm1 /tmp/hotplug-disk.qcow vdb
>   sleep 5
>   virsh resume vm1
>   sleep 5
>   virsh suspend vm1
>   virsh detach-disk vm1 /tmp/hotplug-disk.qcow vdb
>   sleep 5
>   virsh resume vm1
>   sleep 5
> done
> 
> After a while the qemu process crashed with:
> 
> Program received signal SIGSEGV, Segmentation fault.
> qemu_bh_delete (bh=0x0) at async.c:119
> 119	    bh->scheduled = 0;
> 
> #0  qemu_bh_delete (bh=0x0) at async.c:119
> #1  0x00007f0917b3fe80 in virtio_blk_dma_restart_bh (opaque=0x7f0919136c00)
> at /usr/src/debug/qemu-kvm-1.2.0/hw/virtio-blk.c:440
> #2  0x00007f0917971026 in qemu_bh_poll () at async.c:71
> #3  0x00007f0917a8e7f3 in main_loop_wait (nonblocking=<optimized out>) at
> main-loop.c:506
> #4  0x00007f091796ad63 in main_loop () at
> /usr/src/debug/qemu-kvm-1.2.0/vl.c:1643
> #5  main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>)
> at /usr/src/debug/qemu-kvm-1.2.0/vl.c:3792
> 
> # rpm -q qemu libvirt
> qemu-1.2.2-6.fc18.x86_64
> libvirt-0.10.2.3-1.fc18.x86_64
> 
> We don't have any real proof that it's exactly the same issue even though I
> feel that there's an high chance that it is.
> Qemu probably needs to fix this anyway.

So why didn't we move the bug to qemu?

(In reply to comment #8)
> Yes the qemu process crashed for some reason. There's no trace of the reason
> on Dafna's host but I have been able to reproduce the issue looping a
> pause/hot(un)plug/resume:
> 
> while true; do
>   virsh suspend vm1
>   virsh attach-disk vm1 /tmp/hotplug-disk.qcow vdb
>   sleep 5
>   virsh resume vm1
>   sleep 5
>   virsh suspend vm1
>   virsh detach-disk vm1 /tmp/hotplug-disk.qcow vdb
>   sleep 5
>   virsh resume vm1
>   sleep 5
> done
> 
> After a while the qemu process crashed with:
> 
> Program received signal SIGSEGV, Segmentation fault.
> qemu_bh_delete (bh=0x0) at async.c:119
> 119	    bh->scheduled = 0;
> 
> #0  qemu_bh_delete (bh=0x0) at async.c:119
> #1  0x00007f0917b3fe80 in virtio_blk_dma_restart_bh (opaque=0x7f0919136c00)
> at /usr/src/debug/qemu-kvm-1.2.0/hw/virtio-blk.c:440
> #2  0x00007f0917971026 in qemu_bh_poll () at async.c:71
> #3  0x00007f0917a8e7f3 in main_loop_wait (nonblocking=<optimized out>) at
> main-loop.c:506
> #4  0x00007f091796ad63 in main_loop () at
> /usr/src/debug/qemu-kvm-1.2.0/vl.c:1643
> #5  main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>)
> at /usr/src/debug/qemu-kvm-1.2.0/vl.c:3792
> 
> # rpm -q qemu libvirt
> qemu-1.2.2-6.fc18.x86_64
> libvirt-0.10.2.3-1.fc18.x86_64
> 
> We don't have any real proof that it's exactly the same issue even though I
> feel that there's an high chance that it is.
> Qemu probably needs to fix this anyway.

I tried it with the scenario of the comment #8 for more than 10 times, but did not met this issue.

host info:
kernel-2.6.32-369.el6.x86_64
qemu-kvm-0.12.1.2-2.360.el6.x86_64
guest info:
kernel-2.6.32-369.el6.x86_64

Steps:
1.boot a guest with '-global PIIX4_PM.disable_s3=0'.
e.g:# /usr/libexec/qemu-kvm -S -M rhel6.4.0 -cpu host -enable-kvm -m 2048 -smp 2,sockets=2,cores=1,threads=1 -no-kvm-pit-reinjection -name sluo-test -uuid b18fdd6c-a213-4022-9ca4-5d07225e40b0 -rtc base=localtime,clock=host,driftfix=slew -device virtio-serial-pci,id=virtio-serial0,max_ports=16,vectors=0,bus=pci.0,addr=0x3 -chardev socket,id=channel1,path=/tmp/helloworld1,server,nowait -device virtserialport,chardev=channel1,name=com.redhat.rhevm.vdsm,bus=virtio-serial0.0,id=port1 -chardev socket,id=channel2,path=/tmp/helloworld2,server,nowait -device virtserialport,chardev=channel2,name=com.redhat.rhevm.vdsm,bus=virtio-serial0.0,id=port2 -drive file=/home/RHEL-Server-6.4-64.qcow2,if=none,id=drive-system-disk,format=qcow2,cache=none,aio=native,werror=stop,rerror=stop,serial=QEMU-DISK1 -device virtio-blk-pci,bus=pci.0,addr=0x4,drive=drive-system-disk,id=system-disk,bootindex=1 -netdev tap,id=hostnet0,vhost=off,script=/etc/qemu-ifup -device virtio-net-pci,netdev=hostnet0,id=virtio-net-pci0,mac=08:2e:5f:0a:1d:b1,bus=pci.0,addr=0x5,bootindex=2 -device virtio-balloon-pci,id=ballooning,bus=pci.0,addr=0x6 -global PIIX4_PM.disable_s3=0 -global PIIX4_PM.disable_s4=0 -serial unix:/tmp/ttyS0,server,nowait -qmp tcp:0:4444,server,nowait -k en-us -boot menu=on -vnc :1 -spice disable-ticketing,port=5931 -vga qxl -monitor stdio
2.suspend the guest.
guest] # pm-suspend
3.do hot-plug a virtio-blk data disk.
(qemu) __com.redhat_drive_add file=/home/my-data-disk.raw,id=drive-data-disk,format=raw,cache=none,aio=native
(qemu) device_add virtio-blk-pci,bus=pci.0,addr=0x7,drive=drive-data-disk,id=data-disk
4.wait a moment then resuming the guest.
(qemu) system_wakeup
5.wait a moment then do S3 again.
guest] # pm-suspend
6.hot-remove the data disk.
(qemu) device_del data-disk
7.resuming the guest after a while.
(qemu) system_wakeup
8.repeat the step2 to step7 for loop.

Results:
test it for 10 times, but did not met any promblem, both qemu, guest and host works well.

tried it with anther scenario can hit it, qemu core dump.

host info:
kernel-2.6.32-369.el6.x86_64
qemu-kvm-0.12.1.2-2.360.el6.x86_64
guest info:
kernel-2.6.32-369.el6.x86_64

Steps:
1.boot a guest with '-global PIIX4_PM.disable_s3=0'.
e.g:# /usr/libexec/qemu-kvm -S -M rhel6.4.0 -cpu host -enable-kvm -m 2048 -smp 2,sockets=2,cores=1,threads=1 -no-kvm-pit-reinjection -name sluo-test -uuid b18fdd6c-a213-4022-9ca4-5d07225e40b0 -rtc base=localtime,clock=host,driftfix=slew -device virtio-serial-pci,id=virtio-serial0,max_ports=16,vectors=0,bus=pci.0,addr=0x3 -chardev socket,id=channel1,path=/tmp/helloworld1,server,nowait -device virtserialport,chardev=channel1,name=com.redhat.rhevm.vdsm,bus=virtio-serial0.0,id=port1 -chardev socket,id=channel2,path=/tmp/helloworld2,server,nowait -device virtserialport,chardev=channel2,name=com.redhat.rhevm.vdsm,bus=virtio-serial0.0,id=port2 -drive file=/home/RHEL-Server-6.4-64.qcow2,if=none,id=drive-system-disk,format=qcow2,cache=none,aio=native,werror=stop,rerror=stop,serial=QEMU-DISK1 -device virtio-blk-pci,bus=pci.0,addr=0x4,drive=drive-system-disk,id=system-disk,bootindex=1 -netdev tap,id=hostnet0,vhost=off,script=/etc/qemu-ifup -device virtio-net-pci,netdev=hostnet0,id=virtio-net-pci0,mac=08:2e:5f:0a:1d:b1,bus=pci.0,addr=0x5,bootindex=2 -device virtio-balloon-pci,id=ballooning,bus=pci.0,addr=0x6 -global PIIX4_PM.disable_s3=0 -global PIIX4_PM.disable_s4=0 -serial unix:/tmp/ttyS0,server,nowait -qmp tcp:0:4444,server,nowait -k en-us -boot menu=on -vnc :1 -spice disable-ticketing,port=5931 -vga qxl -monitor stdio
2.stop the guest.
(qemu) stop
3.do hot-plug a virtio-blk data disk.
(qemu) __com.redhat_drive_add file=/home/my-data-disk.raw,id=drive-data-disk,format=raw,cache=none,aio=native
(qemu) device_add virtio-blk-pci,bus=pci.0,addr=0x7,drive=drive-data-disk,id=data-disk
4.wait a moment then resuming the guest.
(qemu) cont
5.wait a moment then do stop it again.
(qemu) stop
6.hot-remove the data disk.
(qemu) device_del data-disk
7.resuming the guest after a while.
(qemu) cont
8.repeat the step2 to step7 for loop.

Results:
after some times repeat testing, the qemu-kvm will core dump.
(qemu) Segmentation fault (core dumped)

Program terminated with signal 11, Segmentation fault.
#0  virtio_blk_handle_request (req=0x21, mrb=0x7fff44bea580) at /usr/src/debug/qemu-kvm-0.12.1.2/hw/virtio-blk.c:379
379	    if (req->elem.out_num < 1 || req->elem.in_num < 1) {
(gdb) bt
#0  virtio_blk_handle_request (req=0x21, mrb=0x7fff44bea580) at /usr/src/debug/qemu-kvm-0.12.1.2/hw/virtio-blk.c:379
#1  0x00007f8972acfe4b in virtio_blk_dma_restart_bh (opaque=0x7f89747eedf0)
    at /usr/src/debug/qemu-kvm-0.12.1.2/hw/virtio-blk.c:471
#2  0x00007f8972af2161 in qemu_bh_poll () at /usr/src/debug/qemu-kvm-0.12.1.2/async.c:70
#3  0x00007f8972abb479 in main_loop_wait (timeout=1000) at /usr/src/debug/qemu-kvm-0.12.1.2/vl.c:4017
#4  0x00007f8972add9ea in kvm_main_loop () at /usr/src/debug/qemu-kvm-0.12.1.2/qemu-kvm.c:2244
#5  0x00007f8972abe078 in main_loop (argc=58, argv=<value optimized out>, envp=<value optimized out>)
    at /usr/src/debug/qemu-kvm-0.12.1.2/vl.c:4187
#6  main (argc=58, argv=<value optimized out>, envp=<value optimized out>) at /usr/src/debug/qemu-kvm-0.12.1.2/vl.c:6526
(gdb) bt full
#0  virtio_blk_handle_request (req=0x21, mrb=0x7fff44bea580) at /usr/src/debug/qemu-kvm-0.12.1.2/hw/virtio-blk.c:379
No locals.
#1  0x00007f8972acfe4b in virtio_blk_dma_restart_bh (opaque=0x7f89747eedf0)
    at /usr/src/debug/qemu-kvm-0.12.1.2/hw/virtio-blk.c:471
        s = 0x7f89747eedf0
        req = 0x21
        mrb = {blkreq = {{sector = 0, nb_sectors = 0, qiov = 0x0, cb = 0, opaque = 0x0, error = 0} <repeats 32 times>}, 
          num_writes = 0, old_bs = 0x0}
#2  0x00007f8972af2161 in qemu_bh_poll () at /usr/src/debug/qemu-kvm-0.12.1.2/async.c:70
        bh = <value optimized out>
        bhp = <value optimized out>
        next = 0x7f89747eefd0
        ret = 1
        nesting = 1
#3  0x00007f8972abb479 in main_loop_wait (timeout=1000) at /usr/src/debug/qemu-kvm-0.12.1.2/vl.c:4017
        ioh = <value optimized out>
        rfds = {fds_bits = {1, 0 <repeats 15 times>}}
        wfds = {fds_bits = {0 <repeats 16 times>}}
        xfds = {fds_bits = {0 <repeats 16 times>}}
        ret = 1
        nfds = 38
        tv = {tv_sec = 0, tv_usec = 999996}
#4  0x00007f8972add9ea in kvm_main_loop () at /usr/src/debug/qemu-kvm-0.12.1.2/qemu-kvm.c:2244
        fds = {26, 27}
        mask = {__val = {268443712, 0 <repeats 15 times>}}
        sigfd = 28
---Type <return> to continue, or q <return> to quit---
#5  0x00007f8972abe078 in main_loop (argc=58, argv=<value optimized out>, envp=<value optimized out>)
    at /usr/src/debug/qemu-kvm-0.12.1.2/vl.c:4187
        r = <value optimized out>
#6  main (argc=58, argv=<value optimized out>, envp=<value optimized out>) at /usr/src/debug/qemu-kvm-0.12.1.2/vl.c:6526
        gdbstub_dev = 0x0
        i = <value optimized out>
        snapshot = 0
        linux_boot = 0
        initrd_filename = 0x0
        kernel_filename = 0x0
        kernel_cmdline = 0x7f8972c703cf ""
        boot_devices = "cad", '\000' <repeats 29 times>
        ds = <value optimized out>
        dcl = <value optimized out>
        cyls = 0
        heads = 0
        secs = 0
        translation = 0
        hda_opts = 0x7f8972fca630
        opts = <value optimized out>
        olist = <value optimized out>
        optind = 58
        optarg = 0x7fff44bee7ed "stdio"
        loadvm = 0x0
        machine = 0x7f8972fc4020
        cpu_model = 0x7fff44bee2f0 "host"
---Type <return> to continue, or q <return> to quit---
        fds = {1923317760, 32649}
        tb_size = 0
        pid_file = 0x0
        incoming = 0x0
        fd = 0
        pwd = 0x0
        chroot_dir = 0x0
        run_as = 0x0
        env = <value optimized out>
        show_vnc_port = 0
        defconfig = <value optimized out>
        defconfig_verbose = <value optimized out>
(gdb)

Also tried the same testing with virtio-scsi device, but did not meet this issue. So this issue only happen in virtio-blk device.

Reproduced with

$ for ((i=0; i<100; i++)); do echo stop; echo __com.redhat_drive_add file=tmp.qcow2,id=hotdrive$i; echo device_add virtio-blk-pci,drive=hotdrive$i,id=hotdisk$i,addr=7; sleep 3; echo c; sleep 3; echo stop; echo device_del hotdisk$i; sleep 3; echo c; sleep 3; done | socat STDIO UNIX:test-hmp

where test-hmp is a human monitor.

I get varying backtraces, after a varying number of iterations.

MALLOC_PERTURB_ doesn't seem to make it less random.

Also reproduced under valgrind.  Which complains a lot.  Maybe I can
find a clue there.

I tried to reproduce with upstream QEMU, but couldn't.  Maybe I can
find a clue in the list of upstream commits we don't have.

(In reply to Markus Armbruster from comment #17)
> Reproduced with
> 
> $ for ((i=0; i<100; i++)); do echo stop; echo __com.redhat_drive_add
> file=tmp.qcow2,id=hotdrive$i; echo device_add
> virtio-blk-pci,drive=hotdrive$i,id=hotdisk$i,addr=7; sleep 3; echo c; sleep
> 3; echo stop; echo device_del hotdisk$i; sleep 3; echo c; sleep 3; done |
> socat STDIO UNIX:test-hmp
> 
> where test-hmp is a human monitor.
> 
> I get varying backtraces, after a varying number of iterations.
> 
> MALLOC_PERTURB_ doesn't seem to make it less random.
> 
> Also reproduced under valgrind.  Which complains a lot.  Maybe I can
> find a clue there.
> 
> I tried to reproduce with upstream QEMU, but couldn't.  Maybe I can
> find a clue in the list of upstream commits we don't have.

This looks like the missing qemu_del_vm_change_state_handler(s->change) call in virtio_blk_exit().  It was fixed upstream in:

  commit 69b302b2044a9a0f6d157d25b39a91ff7124c61f
  Author: Christian Borntraeger <borntraeger.com>
  Date:   Fri Feb 22 14:37:10 2013 +0100

      virtio-blk: fix unplug + virsh reboot

Laszlo backported this commit into RHEL 6.x qemu-kvm:

  commit 44d9306ede26ea2881e6c1f104b901be647022a8
  Author: Laszlo Ersek <lersek>
  Date:   Thu May 9 10:27:50 2013 +0200

    virtio-blk: fix unplug + virsh reboot
    
    RH-Author: Laszlo Ersek <lersek>
    Message-id: <1368095270-21681-1-git-send-email-lersek>
    Patchwork-id: 51208
    O-Subject: [RHEL-6.5 qemu-kvm 869586 PATCH] virtio-blk: fix unplug + virsh reboot
    Bugzilla: 869586

I can reproduce the bug with a qemu-kvm built from commit 44d9306^, but not with one built from commit 44d9306.  Closing as duplicate.  Stefan, thanks a lot for the pointer!

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