[Qemu-devel] Intermittent e1000 failure on qemu-kvm 1.0

[Qemu-devel] Intermittent e1000 failure on qemu-kvm 1.0

[Chris Webb]

I have an interesting bug with the e1000 emulation in qemu-kvm 1.0. I've
spent a bit of time trying to track it down, but the behaviour is
sufficiently odd that I'm rather baffled.

The public networking on our VMs consists of a bridge to which the physical
nic is enslaved, a tap interface created for each VM, and qemu-kvm instances
with 

  -netdev tap,id=vlan.0,ifname=tap1,script=no,downscript=no
  -device e1000,id=nic.0,mac=02:00:54:2d:08:f2,netdev=vlan.0

arguments. There are all sorts of ebtables and iptables rules in place
during normal operation of our clusters but I can reproduce the problem by
hand with all of these removed, so I don't think they're implicated.

We initially saw a problem after an upgrade from 0.15.x to 1.0. Upon running
the VMs with the same command line as before, we saw a large number of boot
failures where the guest had apparently come up without networking. Killing
and restarting these VMs generally fixed them. Now on the same hosts, we see
problems with about one e1000-using VM in twenty, strangely much less
frequent than during the mass reboot, and apparently at random.

Because it's an intermittent fault, it's been a bit amusing to reproduce! My
best recipe for reproducing it by hand is to create a standard Debian 6.0
install in a VM, statically configure its networking so it works correctly
for the network attached to br0, and add something like

  curl -s http://www.google.com/ >/dev/null && poweroff

to /etc/rc.local. I can then start qemus in a loop until I get one with
broken networking, typically after twenty or so boots:

  N=1; while true; do
    echo "Starting VM $N:"
    tunctl -t tap1
    brctl addif br0 tap1
    ip link set tap1 up
    qemu-kvm -m 1024 -smp 1 -cpu host -nodefaults -usbdevice tablet \
             -vga cirrus -vnc :1 -drive file=reboot2.img,if=ide,index=0 \
             -netdev tap,id=vlan.0,ifname=tap1,script=no,downscript=no \
             -device e1000,id=nic.0,mac=02:00:54:2d:08:f2,netdev=vlan.0
    tunctl -d tap1
    sleep 1 && echo
    let N++
  done

My test host is running linux 3.2.2, but I've reproduced on an earlier
2.6.39.2 kernel on another host as well. It's definitely present in both
mainline qemu and qemu-kvm 1.0.

That particular guest is running a 2.6.32 kernel but actually the problem
isn't kernel version specific, nor even linux specific as we've seen it on
windows VMs too.

There are at least two things I can do which apparently cause the guests to
always work fine. One is to remove the -usbdevice tablet in the above. The
second is to replace 

  -netdev tap,id=vlan.0,ifname=tap1,script=no,downscript=no

with -netdev user,id=vlan.0 and reconfigure the guest networking to match
the correct usermode networking ip address, netmask and gateway.

This is a bit puzzling to me. The first fix naively suggests something wrong
with the device emulation in the guest, whereas the second fix would point
at something wrong in qemu code that glues the guest to the tap interface.
However, the problem also never happens with virtio or rtl8139 devices.

Once I've got a guest with broken networking, the network stays down even if
I do things like 'ip link set eth0 down; sleep 5; ip link set eth0 up'.
Killing and restarting the same VM, it runs fine next time.

Any suggestions of anything I could do to better pin down this one would be
very gratefully received!

Best wishes,

Chris.

Re: [Qemu-devel] Intermittent e1000 failure on qemu-kvm 1.0

[Stefan Hajnoczi]

On Mon, Apr 02, 2012 at 04:37:23PM +0100, Chris Webb wrote:
> We initially saw a problem after an upgrade from 0.15.x to 1.0.

Perhaps git-bisect(1) can help you track down the change that introduced
this between 0.15 and 1.0.

> Once I've got a guest with broken networking, the network stays down even if
> I do things like 'ip link set eth0 down; sleep 5; ip link set eth0 up'.
> Killing and restarting the same VM, it runs fine next time.

It sounds like this is not the issue, but are you sure the bridge has
forwarding delay set to 0 or Spanning Tree Protocol disabled?  With STP
enabled no traffic will be forwarded by the bridge for a configured
timeout, and depending on the timing of your VM bootup you could see
weird things.  You can check with brctl showstp br0.

Stefan

Re: [Qemu-devel] Intermittent e1000 failure on qemu-kvm 1.0

[Chris Webb]

Stefan Hajnoczi <stefanha@gmail.com> writes:

> On Mon, Apr 02, 2012 at 04:37:23PM +0100, Chris Webb wrote:
> > We initially saw a problem after an upgrade from 0.15.x to 1.0.
> 
> Perhaps git-bisect(1) can help you track down the change that introduced
> this between 0.15 and 1.0.

Hi. I attempted this, but the bug is so intermittent and there are so many
unrelated red-herring breakages along the branchy path between the two that
I had to abandon the effort after a week I'm afraid. It's phenomenally time
consuming, unlike any other bug I've tried to bisect.

> It sounds like this is not the issue, but are you sure the bridge has
> forwarding delay set to 0 or Spanning Tree Protocol disabled?  With STP
> enabled no traffic will be forwarded by the bridge for a configured
> timeout, and depending on the timing of your VM bootup you could see
> weird things.  You can check with brctl showstp br0.

No STP enabled, but the networking is permanently broken on these guests in
any case, not just slow to get started. Usually they've been sat there for
half an hour or more by the time I get back to the stopped reboot loop, and
I left one broken over a weekend without it fixing itself. The network is
statically configured, so if it were down temporarily and came back, pings
would then start working fine.

Cheers,

Chris.

Re: [Qemu-devel] Intermittent e1000 failure on qemu-kvm 1.0

[Stefan Hajnoczi]

On Tue, Apr 3, 2012 at 9:13 AM, Chris Webb <chris@arachsys.com> wrote:
> Stefan Hajnoczi <stefanha@gmail.com> writes:
>> On Mon, Apr 02, 2012 at 04:37:23PM +0100, Chris Webb wrote:
>> It sounds like this is not the issue, but are you sure the bridge has
>> forwarding delay set to 0 or Spanning Tree Protocol disabled?  With STP
>> enabled no traffic will be forwarded by the bridge for a configured
>> timeout, and depending on the timing of your VM bootup you could see
>> weird things.  You can check with brctl showstp br0.
>
> No STP enabled, but the networking is permanently broken on these guests in
> any case, not just slow to get started. Usually they've been sat there for
> half an hour or more by the time I get back to the stopped reboot loop, and
> I left one broken over a weekend without it fixing itself. The network is
> statically configured, so if it were down temporarily and came back, pings
> would then start working fine.

In a case like this it might be most effective to catch a VM in the
bad state and then go in with gdb to see what is broken.  The basic
approach would be putting breakpoints on the e1000 device model's
transmit/receive paths to see if the guest is giving us packets and
whether the tap device is transmitting/receiving.  If guest and host
appear to be working then QEMU's e1000 model must be in a bad state
and it's a question of looking at the tx/rx rings and other hardware
emulation state to figure out what went wrong.

Have you tried unloading the e1000 kernel module inside the guest and
then modprobing it again?  Does this "fix" the issue?

Stefan

Re: [Qemu-devel] Intermittent e1000 failure on qemu-kvm 1.0

[Chris Webb]

Stefan Hajnoczi <stefanha@gmail.com> writes:

> In a case like this it might be most effective to catch a VM in the
> bad state and then go in with gdb to see what is broken.  The basic
> approach would be putting breakpoints on the e1000 device model's
> transmit/receive paths to see if the guest is giving us packets and
> whether the tap device is transmitting/receiving.  If guest and host
> appear to be working then QEMU's e1000 model must be in a bad state
> and it's a question of looking at the tx/rx rings and other hardware
> emulation state to figure out what went wrong.

Hi Stefan. I tried setting a breakpoint on start_xmit, but the qemu blew up
when I hit it:

(gdb) break /home/root/packages/qemu-kvm-1.0/src-hrw66F/hw/e1000.c:start_xmit
Function "start_xmit" not defined.
Make breakpoint pending on future shared library load? (y or [n]) n
(gdb) break /home/root/packages/qemu-kvm-1.0/src-hrw66F/hw/e1000.c:528       
Breakpoint 1 at 0x46dcd6: file /home/root/packages/qemu-kvm-1.0/src-hrw66F/hw/e1000.c, line 528.
(gdb) cont
Continuing.

Program terminated with signal SIGTRAP, Trace/breakpoint trap.
The program no longer exists.

I assume this is some subtlety with breakpointing threaded code?

However, along these lines, I note that the guest appears to have received
packets, though this count is stuck at 1993 bytes. The TX count marches upwards
as I ping outbound from the guest.

If I attach a tcpdump to tap1 on the host, I see the ARP requests going out and
apparently no reply:

0024# tcpdump -i tap1
tcpdump: WARNING: tap1: no IPv4 address assigned
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on tap1, link-type EN10MB (Ethernet), capture size 65535 bytes
12:08:35.654992 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
12:08:36.654976 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
12:08:37.654975 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
12:08:38.670933 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
12:08:39.670922 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
12:08:40.670908 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28

Looking on br0, I do seem to see the replies:

12:12:53.509471 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 84.45.8.129 tell 84.45.8.242, length 28
12:12:53.509914 ARP, Ethernet (len 6), IPv4 (len 4), Reply 84.45.8.129 is-at 00:13:c3:35:a6:42 (oui Unknown), length 46
12:12:54.509455 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 84.45.8.129 tell 84.45.8.242, length 28
12:12:54.509875 ARP, Ethernet (len 6), IPv4 (len 4), Reply 84.45.8.129 is-at 00:13:c3:35:a6:42 (oui Unknown), length 46
12:12:55.509447 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 84.45.8.129 tell 84.45.8.242, length 28
12:12:55.509878 ARP, Ethernet (len 6), IPv4 (len 4), Reply 84.45.8.129 is-at 00:13:c3:35:a6:42 (oui Unknown), length 46
12:12:56.525424 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 84.45.8.129 tell 84.45.8.242, length 28
12:12:56.525854 ARP, Ethernet (len 6), IPv4 (len 4), Reply 84.45.8.129 is-at 00:13:c3:35:a6:42 (oui Unknown), length 46
12:12:57.525408 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 84.45.8.129 tell 84.45.8.242, length 28
12:12:57.525837 ARP, Ethernet (len 6), IPv4 (len 4), Reply 84.45.8.129 is-at 00:13:c3:35:a6:42 (oui Unknown), length 46

but they never get to tap1 despite STP being disabled and no bridge port
filtering:

  # ebtables -L
  Bridge table: filter

  Bridge chain: INPUT, entries: 0, policy: ACCEPT

  Bridge chain: FORWARD, entries: 0, policy: ACCEPT

  Bridge chain: OUTPUT, entries: 0, policy: ACCEPT

  # brctl show br0
  bridge name     bridge id               STP enabled     interfaces
  br0             8000.002590224ffa       no              eth0


This looks uncannily like a kernel problem doesn't it? However, remove the
-usbdevice tablet, and it goes away, which is truly weird! I've just done a
hundred successful reboots without it once again to confirm to myself that I'm
definitely not imagining that behaviour.

> Have you tried unloading the e1000 kernel module inside the guest and
> then modprobing it again?  Does this "fix" the issue?

Hadn't thought of that, but no, it apparently has no effect. It's still broken
after I rmmod it, modprobe it again, and reconfigure the networking.

Cheers,

Chris.

Re: [Qemu-devel] Intermittent e1000 failure on qemu-kvm 1.0

[Stefan Hajnoczi]

On Tue, Apr 3, 2012 at 1:42 PM, Chris Webb <chris@arachsys.com> wrote:
> Stefan Hajnoczi <stefanha@gmail.com> writes:
>
>> In a case like this it might be most effective to catch a VM in the
>> bad state and then go in with gdb to see what is broken.  The basic
>> approach would be putting breakpoints on the e1000 device model's
>> transmit/receive paths to see if the guest is giving us packets and
>> whether the tap device is transmitting/receiving.  If guest and host
>> appear to be working then QEMU's e1000 model must be in a bad state
>> and it's a question of looking at the tx/rx rings and other hardware
>> emulation state to figure out what went wrong.
>
> Hi Stefan. I tried setting a breakpoint on start_xmit, but the qemu blew up
> when I hit it:
>
> (gdb) break /home/root/packages/qemu-kvm-1.0/src-hrw66F/hw/e1000.c:start_xmit
> Function "start_xmit" not defined.
> Make breakpoint pending on future shared library load? (y or [n]) n
> (gdb) break /home/root/packages/qemu-kvm-1.0/src-hrw66F/hw/e1000.c:528
> Breakpoint 1 at 0x46dcd6: file /home/root/packages/qemu-kvm-1.0/src-hrw66F/hw/e1000.c, line 528.
> (gdb) cont
> Continuing.
>
> Program terminated with signal SIGTRAP, Trace/breakpoint trap.
> The program no longer exists.
>
> I assume this is some subtlety with breakpointing threaded code?

No, that's weird.  I would have simply tried "b start_xmit" and as
long as the binary has symbols gdb would know what to do.

> However, along these lines, I note that the guest appears to have received
> packets, though this count is stuck at 1993 bytes. The TX count marches upwards
> as I ping outbound from the guest.
>
> If I attach a tcpdump to tap1 on the host, I see the ARP requests going out and
> apparently no reply:
>
> 0024# tcpdump -i tap1
> tcpdump: WARNING: tap1: no IPv4 address assigned
> tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
> listening on tap1, link-type EN10MB (Ethernet), capture size 65535 bytes
> 12:08:35.654992 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
> 12:08:36.654976 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
> 12:08:37.654975 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
> 12:08:38.670933 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
> 12:08:39.670922 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
> 12:08:40.670908 ARP, Request who-has 84.45.8.129 tell 84.45.8.242, length 28
>
> Looking on br0, I do seem to see the replies:
>
> 12:12:53.509471 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 84.45.8.129 tell 84.45.8.242, length 28
> 12:12:53.509914 ARP, Ethernet (len 6), IPv4 (len 4), Reply 84.45.8.129 is-at 00:13:c3:35:a6:42 (oui Unknown), length 46
> 12:12:54.509455 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 84.45.8.129 tell 84.45.8.242, length 28
> 12:12:54.509875 ARP, Ethernet (len 6), IPv4 (len 4), Reply 84.45.8.129 is-at 00:13:c3:35:a6:42 (oui Unknown), length 46
> 12:12:55.509447 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 84.45.8.129 tell 84.45.8.242, length 28
> 12:12:55.509878 ARP, Ethernet (len 6), IPv4 (len 4), Reply 84.45.8.129 is-at 00:13:c3:35:a6:42 (oui Unknown), length 46
> 12:12:56.525424 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 84.45.8.129 tell 84.45.8.242, length 28
> 12:12:56.525854 ARP, Ethernet (len 6), IPv4 (len 4), Reply 84.45.8.129 is-at 00:13:c3:35:a6:42 (oui Unknown), length 46
> 12:12:57.525408 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 84.45.8.129 tell 84.45.8.242, length 28
> 12:12:57.525837 ARP, Ethernet (len 6), IPv4 (len 4), Reply 84.45.8.129 is-at 00:13:c3:35:a6:42 (oui Unknown), length 46
>
> but they never get to tap1 despite STP being disabled and no bridge port
> filtering:
>
>  # ebtables -L
>  Bridge table: filter
>
>  Bridge chain: INPUT, entries: 0, policy: ACCEPT
>
>  Bridge chain: FORWARD, entries: 0, policy: ACCEPT
>
>  Bridge chain: OUTPUT, entries: 0, policy: ACCEPT
>
>  # brctl show br0
>  bridge name     bridge id               STP enabled     interfaces
>  br0             8000.002590224ffa       no              eth0
>
>
> This looks uncannily like a kernel problem doesn't it? However, remove the
> -usbdevice tablet, and it goes away, which is truly weird! I've just done a
> hundred successful reboots without it once again to confirm to myself that I'm
> definitely not imagining that behaviour.

Are you sure no other guest has the same MAC address or IP address?
This weird behavior sounds similar to what happens when you have
multiple devices on a network using the same address - the results are
very confusing :).

Stefan

Re: [Qemu-devel] Intermittent e1000 failure on qemu-kvm 1.0

[Chris Webb]

Stefan Hajnoczi <stefanha@gmail.com> writes:

> No, that's weird.  I would have simply tried "b start_xmit" and as
> long as the binary has symbols gdb would know what to do.

I'll get another one and give it a go. There wasn't any particular reason I
gave a line number rather than a function except that I worried there might
be start_xmit in a variety of different nic models compiled into qemu so I
might end up setting the breakpoint on the wrong one. b hw/e1000.c:start_xmit
maybe?

> Are you sure no other guest has the same MAC address or IP address?
> This weird behavior sounds similar to what happens when you have
> multiple devices on a network using the same address - the results are
> very confusing :).

Yes, I agree! However, in this case there's no other guest with the same MAC
or IP address on the network. I've explicitly rechecked this to be sure, and
also deliberately varied the MAC address to something I know can't be
generated by our scripts. In any case, I'm using the same MAC and IP address
for every reboot of this VM, and usually (19 times out of 20) it works fine.

Cheers,

Chris.

Re: [Qemu-devel] Intermittent e1000 failure on qemu-kvm 1.0

[Stefan Hajnoczi]

On Tue, Apr 3, 2012 at 2:41 PM, Chris Webb <chris@arachsys.com> wrote:
> Stefan Hajnoczi <stefanha@gmail.com> writes:
>
>> No, that's weird.  I would have simply tried "b start_xmit" and as
>> long as the binary has symbols gdb would know what to do.
>
> I'll get another one and give it a go. There wasn't any particular reason I
> gave a line number rather than a function except that I worried there might
> be start_xmit in a variety of different nic models compiled into qemu so I
> might end up setting the breakpoint on the wrong one. b hw/e1000.c:start_xmit
> maybe?

There is only one start_xmit() in qemu.

>> Are you sure no other guest has the same MAC address or IP address?
>> This weird behavior sounds similar to what happens when you have
>> multiple devices on a network using the same address - the results are
>> very confusing :).
>
> Yes, I agree! However, in this case there's no other guest with the same MAC
> or IP address on the network. I've explicitly rechecked this to be sure, and
> also deliberately varied the MAC address to something I know can't be
> generated by our scripts. In any case, I'm using the same MAC and IP address
> for every reboot of this VM, and usually (19 times out of 20) it works fine.

The lack of ARP reply is a host networking problem.  Have you checked
host dmesg(1) output just in case there was a kernel message related
to this?

Stefan

Re: [Qemu-devel] Intermittent e1000 failure on qemu-kvm 1.0

[Chris Webb]

Stefan Hajnoczi <stefanha@gmail.com> writes:


> >> Are you sure no other guest has the same MAC address or IP address?
> >> This weird behavior sounds similar to what happens when you have
> >> multiple devices on a network using the same address - the results are
> >> very confusing :).
> >
> > Yes, I agree! However, in this case there's no other guest with the same MAC
> > or IP address on the network. I've explicitly rechecked this to be sure, and
> > also deliberately varied the MAC address to something I know can't be
> > generated by our scripts. In any case, I'm using the same MAC and IP address
> > for every reboot of this VM, and usually (19 times out of 20) it works fine.
> 
> The lack of ARP reply is a host networking problem.  Have you checked
> host dmesg(1) output just in case there was a kernel message related
> to this?

Nothing there I'm afraid. Just the usual

  device tap1 entered promiscuous mode
  ADDRCONF(NETDEV_UP): tap1: link is not ready
  ADDRCONF(NETDEV_CHANGE): tap1: link becomes ready
  br0: port 2(tap1) entering forwarding state
  br0: port 2(tap1) entering forwarding state
  kvm: 20288: cpu0 unhandled rdmsr: 0xc0010112
  kvm: 20288: cpu0 unhandled rdmsr: 0xc0010048
  tap1: no IPv6 routers present
  br0: port 2(tap1) entering forwarding state
  br0: port 2(tap1) entering forwarding state
  br0: port 2(tap1) entering forwarding state
  br0: port 2(tap1) entering forwarding state
  br0: port 2(tap1) entering disabled state

cycle. It looks just the same for a working guest as for a non-working
guest.

Best wishes,

Chris.