QEMU fails during migration and reports "qemu: VQ 0 size 0x80 Guest index 0x2d6 inconsistent with Host index 0x18: delta 0x2be"

[Lucas Meneghel Rodrigues]

This issue is reproducing consistently on automated testing, verified on manual testing (although it may require many tries).

Steps to reproduce:

1) Start a linux guest. The command line used by automated testing was:

10/05 06:48:27 INFO | kvm_vm:1605| MALLOC_PERTURB_=1 /usr/local/autotest/tests/kvm/qemu
10/05 06:48:27 INFO | kvm_vm:1605| -S
10/05 06:48:27 INFO | kvm_vm:1605| -name 'vm1'
10/05 06:48:27 INFO | kvm_vm:1605| -nodefaults
10/05 06:48:27 INFO | kvm_vm:1605| -chardev socket,id=hmp_id_humanmonitor1,path=/tmp/monitor-humanmonitor1-20121005-062311-r6UwQhzg,server,nowait
10/05 06:48:27 INFO | kvm_vm:1605| -mon chardev=hmp_id_humanmonitor1,mode=readline
10/05 06:48:27 INFO | kvm_vm:1605| -chardev socket,id=qmp_id_qmpmonitor1,path=/tmp/monitor-qmpmonitor1-20121005-062311-r6UwQhzg,server,nowait
10/05 06:48:27 INFO | kvm_vm:1605| -mon chardev=qmp_id_qmpmonitor1,mode=control
10/05 06:48:27 INFO | kvm_vm:1605| -chardev socket,id=serial_id_20121005-062311-r6UwQhzg,path=/tmp/serial-20121005-062311-r6UwQhzg,server,nowait
10/05 06:48:27 INFO | kvm_vm:1605| -device isa-serial,chardev=serial_id_20121005-062311-r6UwQhzg
10/05 06:48:27 INFO | kvm_vm:1605| -chardev socket,id=seabioslog_id_20121005-062311-r6UwQhzg,path=/tmp/seabios-20121005-062311-r6UwQhzg,server,nowait
10/05 06:48:27 INFO | kvm_vm:1605| -device isa-debugcon,chardev=seabioslog_id_20121005-062311-r6UwQhzg,iobase=0x402
10/05 06:48:27 INFO | kvm_vm:1605| -device ich9-usb-uhci1,id=usb1
10/05 06:48:27 INFO | kvm_vm:1605| -drive file='/tmp/kvm_autotest_root/images/rhel62-64.qcow2',if=none,cache=none,id=virtio0
10/05 06:48:27 INFO | kvm_vm:1605| -device virtio-blk-pci,drive=virtio0
10/05 06:48:27 INFO | kvm_vm:1605| -device virtio-net-pci,netdev=idbdMz8N,mac='9a:cf:d0:d1:d2:d3',id='ida0Kc7l'
10/05 06:48:27 INFO | kvm_vm:1605| -netdev tap,id=idbdMz8N,fd=21
10/05 06:48:27 INFO | kvm_vm:1605| -m 2048
10/05 06:48:27 INFO | kvm_vm:1605| -smp 2,cores=1,threads=1,sockets=2
10/05 06:48:27 INFO | kvm_vm:1605| -device usb-tablet,id=usb-tablet1,bus=usb1.0,port=1
10/05 06:48:27 INFO | kvm_vm:1605| -vnc :0
10/05 06:48:27 INFO | kvm_vm:1605| -vga std
10/05 06:48:27 INFO | kvm_vm:1605| -rtc base=utc,clock=host,driftfix=none
10/05 06:48:27 INFO | kvm_vm:1605| -boot order=cdn,once=c,menu=off
10/05 06:48:27 INFO | kvm_vm:1605| -enable-kvm

Start a new VM in incoming mode. The example on this bug is using TCP protocol:

10/05 07:18:56 INFO | kvm_vm:1605| MALLOC_PERTURB_=1 /usr/local/autotest/tests/kvm/qemu
10/05 07:18:56 INFO | kvm_vm:1605| -S
10/05 07:18:56 INFO | kvm_vm:1605| -name 'vm1'
10/05 07:18:56 INFO | kvm_vm:1605| -nodefaults
10/05 07:18:56 INFO | kvm_vm:1605| -chardev socket,id=hmp_id_humanmonitor1,path=/tmp/monitor-humanmonitor1-20121005-071855-5QYsCtRS,server,nowait
10/05 07:18:56 INFO | kvm_vm:1605| -mon chardev=hmp_id_humanmonitor1,mode=readline
10/05 07:18:56 INFO | kvm_vm:1605| -chardev socket,id=qmp_id_qmpmonitor1,path=/tmp/monitor-qmpmonitor1-20121005-071855-5QYsCtRS,server,nowait
10/05 07:18:56 INFO | kvm_vm:1605| -mon chardev=qmp_id_qmpmonitor1,mode=control
10/05 07:18:56 INFO | kvm_vm:1605| -chardev socket,id=serial_id_20121005-071855-5QYsCtRS,path=/tmp/serial-20121005-071855-5QYsCtRS,server,nowait
10/05 07:18:56 INFO | kvm_vm:1605| -device isa-serial,chardev=serial_id_20121005-071855-5QYsCtRS
10/05 07:18:56 INFO | kvm_vm:1605| -chardev socket,id=seabioslog_id_20121005-071855-5QYsCtRS,path=/tmp/seabios-20121005-071855-5QYsCtRS,server,nowait
10/05 07:18:56 INFO | kvm_vm:1605| -device isa-debugcon,chardev=seabioslog_id_20121005-071855-5QYsCtRS,iobase=0x402
10/05 07:18:56 INFO | kvm_vm:1605| -device ich9-usb-uhci1,id=usb1
10/05 07:18:56 INFO | kvm_vm:1605| -drive file='/tmp/kvm_autotest_root/images/rhel62-64.qcow2',if=none,cache=none,id=virtio0
10/05 07:18:56 INFO | kvm_vm:1605| -device virtio-blk-pci,drive=virtio0
10/05 07:18:56 INFO | kvm_vm:1605| -device virtio-net-pci,netdev=idERNnUO,mac='9a:cf:d0:d1:d2:d3',id='ideI7zfw'
10/05 07:18:56 INFO | kvm_vm:1605| -netdev tap,id=idERNnUO,fd=32
10/05 07:18:56 INFO | kvm_vm:1605| -m 2048
10/05 07:18:56 INFO | kvm_vm:1605| -smp 2,cores=1,threads=1,sockets=2
10/05 07:18:56 INFO | kvm_vm:1605| -device usb-tablet,id=usb-tablet1,bus=usb1.0,port=1
10/05 07:18:56 INFO | kvm_vm:1605| -vnc :1
10/05 07:18:56 INFO | kvm_vm:1605| -vga std
10/05 07:18:56 INFO | kvm_vm:1605| -rtc base=utc,clock=host,driftfix=none
10/05 07:18:56 INFO | kvm_vm:1605| -boot order=cdn,once=c,menu=off
10/05 07:18:56 INFO | kvm_vm:1605| -enable-kvm
10/05 07:18:56 INFO | kvm_vm:1605| -incoming tcp:0:5200

Start the migration, typing on monitor

10/05 07:18:58 DEBUG|kvm_monito:0177| (monitor humanmonitor1) Sending command 'migrate -d tcp:0:5200'

The VM will start migrating state to the new qemu instance, and at some point it will stop with:

10/05 07:19:10 INFO | aexpect:0786| [qemu output] qemu: VQ 0 size 0x80 Guest index 0x2d6 inconsistent with Host index 0x18: delta 0x2be
10/05 07:19:10 INFO | aexpect:0786| [qemu output] qemu: warning: error while loading state for instance 0x0 of device '0000:00:04.0/virtio-blk'
10/05 07:19:10 INFO | aexpect:0786| [qemu output] load of migration failed
10/05 07:19:10 INFO | aexpect:0786| [qemu output] (Process terminated with status 0)

Due to the large number of migrations executed during a virt job (vm state keeps being passed back and forth many times, using many protocols), we get this problem on every single virt job.

Latest commits we found this issue:

Kernel (kvm.git, avi's tree)
10/05 05:38:12 INFO | git:0153| git commit ID is 1a95620f45155ac523cd1419d89150fbb4eb858b (tag kvm-3.6-2-136-g1a95620)

Userspace (qemu.git)

10/05 06:20:30 INFO | git:0153| git commit ID is a14c74928ba1fdaada515717f4d3c3fa3275d6f7 (tag v1.2.0-546-ga14c749)

[Paolo Bonzini (bonzini)]

Have you bisected it already?

[Lucas Meneghel Rodrigues (lmr)]

No, I haven't. I'll do my best to reserve time this week to do so.

[Andres Lagar-Cavilla (andreslc-x)]

FWIW this one bites me. The bug report seems fairly abandoned ... has this been fixed elsewhere perhaps?

[Andres Lagar-Cavilla (andreslc-x)]

I meant "bites me too" ...

[Lucas Meneghel Rodrigues (lmr)]

Yep, I did let this one slip...

In any case, I don't see this problem anymore, it was fixed a long while ago. Are you trying QEMU from the latest master?

[Thomas Huth (th-huth)]

Closing this ticket now, since it has been fixed according to comment #5.