Bug 867366

Summary: virtio-serial misses irq delivery on migration
Product: [Fedora] Fedora Reporter: Alexander Larsson <alexl>
Component: qemuAssignee: Alon Levy <alevy>
Status: CLOSED CURRENTRELEASE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 18CC: acathrow, amit.shah, bcao, berrange, bsarathy, cfergeau, crobinso, dblechte, dwmw2, dyasny, itamar, juzhang, knoel, pbonzini, rjones, scottt.tw, virt-maint
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-11-27 04:46:08 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
VM xml description
none
Example fix by pushing the message to a bottom half
none
patch to synchronize APIC state upon load none

Description Alexander Larsson 2012-10-17 11:31:38 UTC
I have a problem in my Win7 VM where if I save/restore it via virt-manager the moust stops working, I've tracked this down to the fact that if i save while the vd_agent is running the agent stops working until a vm reboot (even if you restart it).

I've tried to reproduce this with arnons dummy_agent.exe, and with the default arguments (i.e. it keeps writing stuff often) i can't reproduce the problem, but if i have a long delay between the writes then it reproduces the problem. i.e. after restore dummy_agent stops printing "." during mouse moves. And, at this point i start getting:

__spice_char_device_write_buffer_get: internal buf is not available

in the qemu logs, indicating that the write buffers are full, and that the agent is not reading data from it.

I was not able to reproduce any of this on a linux guest, so it seems likely that the issue is in the win32 virtio-serial driver.

Comment 2 Alexander Larsson 2012-10-17 11:38:10 UTC
Note: The host here is really Fedora 18, not RHEL6, but fedora has no virtio-win component.

Comment 3 Mike Cao 2012-10-18 02:49:52 UTC
Hi,Alexander

Could you provide me the guest XML ?

Thanks,
Mike

Comment 4 Alexander Larsson 2012-10-18 07:38:23 UTC
Created attachment 629222 [details]
VM xml description

Comment 5 Alexander Larsson 2012-10-19 08:50:42 UTC
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.

Comment 6 Alexander Larsson 2012-10-22 09:35:30 UTC
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.

Comment 7 Alexander Larsson 2012-10-22 18:16:43 UTC
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?

Comment 8 Alexander Larsson 2012-10-22 18:19:38 UTC
Note: If i disable the call to send_control_event then the problem goes away.

Comment 9 Mike Cao 2012-10-23 07:38:44 UTC
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.

Comment 10 Mike Cao 2012-10-23 07:52:47 UTC
Tried the steps with qemu-kvm from git://git.kernel.org/pub/scm/virt/kvm/qemu-kvm.git still can not reproduce .

Comment 11 Alexander Larsson 2012-10-23 08:38:42 UTC
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.

Comment 12 Mike Cao 2012-10-23 10:30:37 UTC
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

Comment 13 Alexander Larsson 2012-10-23 10:52:42 UTC
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.

Comment 14 Alexander Larsson 2012-10-23 10:53:52 UTC
Created attachment 632023 [details]
Example fix by pushing the message to a bottom half

Comment 15 Alexander Larsson 2012-10-23 15:17:15 UTC
I bisected this to:

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

Comment 16 Alexander Larsson 2012-10-23 16:42:23 UTC
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.

Comment 17 Cole Robinson 2012-10-24 14:41:23 UTC
Hey Alex, thanks for the thorough investigation!

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

Comment 18 Amit Shah 2012-10-25 06:16:30 UTC
(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.

Comment 19 Alexander Larsson 2012-10-25 08:16:34 UTC
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.

Comment 20 Paolo Bonzini 2012-10-25 12:16:13 UTC
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.

Comment 21 Paolo Bonzini 2012-10-25 12:23:08 UTC
... however, this may be a workaround for an APIC or IOAPIC bug.  It's better to bring this upstream.  Please CC jan.kiszka.

Comment 22 Alexander Larsson 2012-10-30 07:54:49 UTC
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.

Comment 23 Paolo Bonzini 2012-10-30 11:58:54 UTC
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.

Comment 24 Paolo Bonzini 2012-10-30 14:58:50 UTC
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.

Comment 25 Alexander Larsson 2012-11-12 13:46:04 UTC
Any progress on this?

Comment 26 Paolo Bonzini 2012-11-14 11:00:04 UTC
Alon was supposed to make a new patch to use a QEMUTimer.  Let's nag him. :)

Comment 27 Alon Levy 2012-11-14 13:11:51 UTC
http://patchwork.ozlabs.org/patch/198902/

Comment 28 Alexander Larsson 2012-11-14 18:12:39 UTC
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.

Comment 29 Alon Levy 2012-11-17 23:42:37 UTC
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

Comment 30 Alexander Larsson 2012-11-19 12:37:44 UTC
Yes. that works for me. Thanks!

Comment 31 Fedora Update System 2012-11-20 16:09:24 UTC
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

Comment 32 Fedora Update System 2012-11-20 20:23:25 UTC
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).

Comment 33 Fedora Update System 2012-11-27 04:46:12 UTC
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.