Bug 867366

Note: The host here is really Fedora 18, not RHEL6, but fedora has no virtio-win component.

Hi,Alexander

Could you provide me the guest XML ?

Thanks,
Mike

Created attachment 629222 [details]
VM xml description

I've been able to reproduce this with the vioser-test.exe app.
I added this to the libvirt desc:
     <channel type='unix'>
      <source mode='bind' path='/tmp/guestfs' />
      <target type='virtio' name='org.windows-kvm.port.1'/>
      <address type='virtio-serial' controller='1' bus='0'/>
    </channel>

And then i ran 
socat /tmp/guestfs -
on the host
and visoser-test.exe in the guest

Initially both read and write tests in vioser-test works, but after a save/restore only the write tests work. The read test hangs forever, never seeing the data from the host.

I've debugged this a bit. It seems like after a save+restore the virtio-serial driver does not respond to any irqs.

During restore we virtio_notify() on the serial device, which eventually raises the pci irq level to 1. However, the driver never responds to this by reading the VIRTIO_PCI_ISR, so the irq level is never cleared, and all later virtio_notify() do nothing since the irq level is already 1.

Got a bit further on this. During restore, virtio_serial_load() gets called, which does:

        host_connected = qemu_get_byte(f);
        if (host_connected != port->host_connected) {
            /*
             * We have to let the guest know of the host connection
             * status change
             */
            send_control_event(port, VIRTIO_CONSOLE_PORT_OPEN,
                               port->host_connected);
        }

send_control_event -> send_control_msg -> virtio_notify -> ... -> pci_set_irq.

This will change the level of the irq from 0 to 1, however, (i guess because we're still loading so the cpu is not running?) the corresponding irq handler is never executed.

This means when we later get real incoming events pci_set_irq will exit early because the level is already 1, so nothing to do. This means we never reach the irq handler in the driver, and thus never reset the irq level back to 0.

How did this ever work? Did something change wrt how irqs are delivered during load?

Note: If i disable the call to send_control_event then the problem goes away.

Tried both upstream qemu-kvm-1.2.0 and qemu-kvm-rhev-0.12.1.2-2.295.el6_3.2.x86_64 via qemu-kvm commandline directly ,can not reproduce this issue 

Following is the steps:
1.Start VM with virito-serial-pci and virtserialport
CLI in qemu-kvm-rhel6
#/usr/libexec/qemu-kvm -M rhel6.3.0 --enable-kvm -m 2G -smp 4 -name win2k8-R2 -uuid 88406e09-8378-4879-89a7-c99f35855ffd -monitor stdio -rtc base=localtime,driftfix=slew -drive file=/home/win7-32.raw,if=none,id=drive-test,format=raw,cache=none,werror=stop,rerror=stop -device ide-drive,drive=drive-test,id=test -netdev tap,id=netdev0 -device e1000,netdev=netdev0,id=hostnet0 -vnc :1 -vga std -device virtio-serial-pci,id=virtio-serial0 -chardev socket,id=chardev0,path=/tmp/tt,server,nowait -device virtserialport,id=port0,name=com.redhat.rhevm.vdsm,chardev=chardev0 -cdrom /usr/share/virtio-win/virtio-win.iso

CLI in upstream qemu-kvm-1.2.0
#x86_64-softmmu/qemu-system-x86_64 --enable-kvm -m 2G -smp 4 -name win2k8-R2 -uuid 88406e09-8378-4879-89a7-c99f35855ffd -monitor stdio -rtc base=localtime,driftfix=slew -drive file=/home/win7-32.raw,if=none,id=drive-test,format=raw,cache=none,werror=stop,rerror=stop -device ide-drive,drive=drive-test,id=test -netdev tap,id=netdev0 -device e1000,netdev=netdev0,id=hostnet0 -vnc :1 -vga std -device virtio-serial-pci,id=virtio-serial0 -chardev socket,id=chardev0,path=/tmp/tt,server,nowait -device virtserialport,id=port0,name=com.redhat.rhevm.vdsm,chardev=chardev0 -cdrom /usr/share/virtio-win/virtio-win.iso

2.install virtio serial driver in the guest (the driver under WXp\x86)

3.Transferring data from host to guest
  3.1 in the guest #vioser-test.exe 
  3.2 on the host # echo mike |nc -U /tmp/tt
  3.3 in the guest press r in vioser-test application terminal

4. Transferring data from guest to host 
  4.1 on the host # nc -U /tmp/tt
  4.2 in the guest #vioser-test.exe press "w"-->enter --->issue "mikecao"-->enter

5.save the guest status to external file
  (qemu) migrate -d "exec:gzip -c > mike.gz"

6. restore it 
CLI in qemu-kvm-rhel6
#/usr/libexec/qemu-kvm -M rhel6.3.0 --enable-kvm -m 2G -smp 4 -name win2k8-R2 -uuid 88406e09-8378-4879-89a7-c99f35855ffd -monitor stdio -rtc base=localtime,driftfix=slew -drive file=/home/win7-32.raw,if=none,id=drive-test,format=raw,cache=none,werror=stop,rerror=stop -device ide-drive,drive=drive-test,id=test -netdev tap,id=netdev0 -device e1000,netdev=netdev0,id=hostnet0 -vnc :1 -vga std -device virtio-serial-pci,id=virtio-serial0 -chardev socket,id=chardev0,path=/tmp/tt,server,nowait -device virtserialport,id=port0,name=com.redhat.rhevm.vdsm,chardev=chardev0 -cdrom /usr/share/virtio-win/virtio-win.iso -incoming "exec:gzip -c -d mike.gz"

CLI in upstream qemu-kvm-1.2.0
#x86_64-softmmu/qemu-system-x86_64 --enable-kvm -m 2G -smp 4 -name win2k8-R2 -uuid 88406e09-8378-4879-89a7-c99f35855ffd -monitor stdio -rtc base=localtime,driftfix=slew -drive file=/home/win7-32.raw,if=none,id=drive-test,format=raw,cache=none,werror=stop,rerror=stop -device ide-drive,drive=drive-test,id=test -netdev tap,id=netdev0 -device e1000,netdev=netdev0,id=hostnet0 -vnc :1 -vga std -device virtio-serial-pci,id=virtio-serial0 -chardev socket,id=chardev0,path=/tmp/tt,server,nowait -device virtserialport,id=port0,name=com.redhat.rhevm.vdsm,chardev=chardev0 -cdrom /usr/share/virtio-win/virtio-win.iso -incoming "exec:gzip -c -d mike.gz"

7.Transferring data from guest to host (repeat step4)

8.Transferring data from guest to host (repeat step8)


Actual Results:
After step 7 ,host could receive data successfully
After step 8 .guest could reeive data successfully.

Tried the steps with qemu-kvm from git://git.kernel.org/pub/scm/virt/kvm/qemu-kvm.git still can not reproduce .

Ah, the reproducing steps are wrong:

3.Transferring data from host to guest
  3.1 in the guest #vioser-test.exe 
  3.2 on the host # echo mike |nc -U /tmp/tt
  3.3 in the guest press r in vioser-test application terminal

This works for me, because by the time we issue the request the data is already in the queue, and there is no need for an interrupt.
If you instead press r before sending data to the guest, so that vioser-test is blocking on the data.

I was able to reproduce it with qemu built from the 1.2.0. tarball with:

x86_64-softmmu/qemu-system-x86_64 --enable-kvm -m 2G -smp 4 -name win7 -uuid 88406e09-8378-4879-89a7-c99f35855ffd -monitor stdio -rtc base=localtime,driftfix=slew -drive file=/home/alex/.local/share/gnome-boxes/images/win7.img,if=none,id=drive-test,format=qcow2,cache=none,werror=stop,rerror=stop -device ide-drive,drive=drive-test,id=test -vga std -device virtio-serial-pci,id=virtio-serial0 -chardev socket,id=chardev0,path=/tmp/guestfs,server,nowait -device virtserialport,id=port0,name=org.windows-kvm.port.1,chardev=chardev0

* in host: socat /tmp/guestfs -
* in guest: run vioser-test.exe
* in quest: typoe "r" + enter
* in host: Type "test" + enter in socat

This gives me:
 ReadFile OK: rcv 5 bytes
 test

Then in qemu:
migrate -d "exec:gzip -c > data.gz"
quit

Then:
x86_64-softmmu/qemu-system-x86_64 --enable-kvm -m 2G -smp 4 -name win7 -uuid 88406e09-8378-4879-89a7-c99f35855ffd -monitor stdio -rtc base=localtime,driftfix=slew -drive file=/home/alex/.local/share/gnome-boxes/images/win7.img,if=none,id=drive-test,format=qcow2,cache=none,werror=stop,rerror=stop -device ide-drive,drive=drive-test,id=test -vga std -device virtio-serial-pci,id=virtio-serial0 -chardev socket,id=chardev0,path=/tmp/guestfs,server,nowait -device virtserialport,id=port0,name=org.windows-kvm.port.1,chardev=chardev0 -incoming "exec:gzip -c -d data.gz"


* in host: socat /tmp/guestfs -
* in guest: Press "r" + enter in vioser-test.exe
* in host: type "test" + enter

Result: No reply to the last read request in the guest.

Thanks ,Alex 

I still can *not* reproduce this bug on qemu-kvm-rhev-0.12.1.2-2.295.el6_3.2.x86_64

I can reproduce this bug on upstream qemu-kvm-1.2

Ok. It turns out that this is not a driver issue, but a qemu 1.2.0 issue, so I've reassigned this to qemu in Fedora 18.

The problem is in the qemu vioserial driver. In particular in virtio-serial-bus.c:virtio_serial_load(). During load of a VM we hit this codepath:

        host_connected = qemu_get_byte(f);
        if (host_connected != port->host_connected) {
            /*
             * We have to let the guest know of the host connection
             * status change
             */
            send_control_event(port, VIRTIO_CONSOLE_PORT_OPEN,
                               port->host_connected);
        }

And if host_connected != port->host_connected (in my testcase in comment #11 host_connected = 1, port->host_connected = 0) we will call send_control_event() which will queue a message in the virtio ring and trigger a irq.

However, for some reason the driver never sees this irq in qemu 1.2.0 (although apparently it does in the RHEL6 qemu). This means that the irq level is set to 1 without the guest knowing it, so it will not serve the irq and clear it. Later messages comming in will also not trigger an irq, as the level is already set.

Alon created a test patch (attached) that moves the sending of the VIRTIO_CONSOLE_PORT_OPEN to a bottom half. This fixed the issue for me, but I don't know why this is needed. Did the handling of irqs during migration change from qemu-kvm 0.12 to 1.2.0?

Also, the fedora package has a patch called 0112-virtio-serial-bus-replay-guest_open-on-migration.patch (not upstream), which introduces a similar codepath:

+        if (port->guest_connected && vsc->guest_open) {
+            /* replay guest open */
+            vsc->guest_open(port);
+        }

This is what causes the original issue (vd_agent breaking) in the same way as the above. So, this also needs to go into a bottom half if that is needed.

Created attachment 632023 [details]
Example fix by pushing the message to a bottom half

I bisected this to:

http://git.qemu.org/?p=qemu.git;a=commit;h=a24b9106fa1ba8de0d62d93b64ebbf83ae6a131a

The bisected commin just changes the default of kernel_irqchip to on. I tried -machine accel=kvm,kernel_irqchip=off with git master, but that crashed qemu during vmload due to some other error. 

My guess is that if that was fixed it would work, and the reason for the change is that the kernel_irqchip support has a different behaviour than the software irq support in the case of a non-running cpu.

Question is, can and do we want to change the kernel_irqchip behaviour or do we want to push the sending of VIRTIO_CONSOLE_PORT_OPEN messages to a bottom half.

Hey Alex, thanks for the thorough investigation!

Amit, thoughts? Alex has an example patch in Comment #14

(In reply to comment #16)
> Question is, can and do we want to change the kernel_irqchip behaviour or do
> we want to push the sending of VIRTIO_CONSOLE_PORT_OPEN messages to a bottom
> half.

We need to find out if the bh will indeed run after the vcpus are started, else we would get similar behaviour as now.  The best solution is to get notifications from the migration code on when the vcpus are started.  See all the notifier_list_notify() calls in migration*.c.  There aren't any notifications done currently on the destination side.  Shouldn't be too difficult to add.

Amit: I verified that the patch in comment #14 indeed fixes the issue for me. so it does seem to trigger after the cpu has been started. But of course, doing this when we get the "notifications are started" seems like a good approach too.

One question is, can we somehow ensure that the messages this sends are guaranteed to be sent before other new messages come in from the host.

Incoming migration is currently blocking, but this is going to change to keep the monitor working during incoming migration.  The change will break the patch of comment #14.

However, you can use a vm_clock timer (with the deadline set to 0 or qemu_get_clock_ns(vm_clock) so that it will immediately expire) instead of a bottom half.  vm_clock timers only run when CPUs are running.

... however, this may be a workaround for an APIC or IOAPIC bug.  It's better to bring this upstream.  Please CC jan.kiszka.

Is anyone working on this? This is a major problem for gnome boxes, as it regularly saves and restores domains (for instance on exit it saves all boxes) and this bug causes the mouse to stop in all win32 guests. I would very much like to see this fixed in F18, as without it windows guests are essentially broken.

Created attachment 635535 [details]
patch to synchronize APIC state upon load

Possible reproducer:

- start the VM

x86_64-softmmu/qemu-system-x86_64 -device virtio-serial-pci -device virtserialport -drive if=virtio,file=/vm/bench.qcow2 --enable-kvm -vnc :1 -m 512

- migrate with "migrate exec:cat>foo.ckp"

- restart the VM

x86_64-softmmu/qemu-system-x86_64 -device virtio-serial-pci -chardev stdio,id=vs0 -device virtserialport,chardev=vs0 -drive if=virtio,file=/vm/bench.qcow2,snapshot=on --enable-kvm -vnc :1 -m 512 -incoming 'exec:cat foo.ckp'

will show "KVM: injection failed, MSI lost (Operation not permitted)".

The reason is that the APIC state is loaded, but it is not synchronized to the hypervisor which thinks the APIC is not enabled.

The patch doesn't fix Alex's bug.

However, Alex reported on IRC that Windows does not use MSI.  In fact, the same reproducer with pci=nomsi reproduces the problem.  After restarting the VM:

- "cat /dev/vport0p1" will not block (as if the host was still unconnected)

- similarly, even writes will remain stuck.

- even network will not work because the NIC shares the interrupt with virtio-serial.

Any progress on this?

Alon was supposed to make a new patch to use a QEMUTimer.  Let's nag him. :)

http://patchwork.ozlabs.org/patch/198902/

That patch fixes the reproducer case in comment 11 for me.

However, its not enough for F18, as it has similar issues in 0411-virtio-serial-bus-replay-guest_open-on-migration.patch which adds this:

+        if (port->guest_connected && vsc->guest_open) {
+            /* replay guest open */
+            vsc->guest_open(port);
+        }

Which also has to happen in a timeout.

Alex, how does this look (or test)? it's on top of the patch heading upstream.

From 5b6831175b21aa5a3405a21dd79e1ef0a81bbdb3 Mon Sep 17 00:00:00 2001
From: Alon Levy <alevy>
Date: Fri, 16 Nov 2012 16:24:47 +0200
Subject: [PATCH 2/2] hw/virtio-serial-bus: replay guest open on destination

This is rewrite of a patch carried in Fedora previously based
on new code upstream, here is the original message, it still applies:
(the original fedora patch was commit id
a9bc20afc1f0604ee81c23b7c67d627e51d2e8d4, this is useful for grepping in
logs, it isn't in upstream)

When migrating a host with with a spice agent running the mouse becomes
non operational after the migration. This is rhbz #725965.

The problem is that after migration spice doesn't know the guest agent
is open.  Spice is just a char dev here. And a chardev cannot query it's
device, the device has to let the chardev know when it is open. Right
now after migration the chardev which is recreated is in it's default
state, which assumes the guest is disconnected.

Char devices carry no information across migration, but the
virtio-serial does already carry the guest_connected state. This patch
passes that bit to the chardev.
---
 hw/virtio-serial-bus.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/hw/virtio-serial-bus.c b/hw/virtio-serial-bus.c
index a028877..a6ec2df 100644
--- a/hw/virtio-serial-bus.c
+++ b/hw/virtio-serial-bus.c
@@ -641,6 +641,7 @@ static void virtio_serial_post_load_timer_cb(void *opaque)
     VirtIOSerial *s = opaque;
     VirtIOSerialPort *port;
     uint8_t host_connected;
+    VirtIOSerialPortClass *vsc;
 
     for (i = 0 ; i < s->post_load.nr_active_ports; ++i) {
         port = s->post_load.connected[i].port;
@@ -653,6 +654,11 @@ static void virtio_serial_post_load_timer_cb(void *opaque)
             send_control_event(port, VIRTIO_CONSOLE_PORT_OPEN,
                                port->host_connected);
         }
+        vsc = VIRTIO_SERIAL_PORT_GET_CLASS(port);
+        if (port->guest_connected && vsc->guest_open) {
+            /* replay guest open */
+            vsc->guest_open(port);
+        }
     }
     g_free(s->post_load.connected);
     s->post_load.connected = NULL;
-- 
1.8.0

Yes. that works for me. Thanks!

qemu-1.2.0-23.fc18 has been submitted as an update for Fedora 18.
https://admin.fedoraproject.org/updates/qemu-1.2.0-23.fc18

Package qemu-1.2.0-23.fc18:
* should fix your issue,
* was pushed to the Fedora 18 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing qemu-1.2.0-23.fc18'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2012-18624/qemu-1.2.0-23.fc18
then log in and leave karma (feedback).

qemu-1.2.0-23.fc18 has been pushed to the Fedora 18 stable repository.  If problems still persist, please make note of it in this bug report.