2.6.13-rc4 - kernel panic - BUG at net/ipv4/tcp_output.c:918

2.6.13-rc4 - kernel panic - BUG at net/ipv4/tcp_output.c:918

[Guillaume Pelat]

Hi,

I've been trying to upgrade kernel from 2.6.12.3 to 2.6.13-rc4 on a 
rather loaded http server, but i'm currently having a kernel panic a few 
minutes only after booting. The bug was reproductible (the crash 
happened after every reboot, with the same backtrace).

Here is the error log:
------------[ cut here ]------------
kernel BUG at net/ipv4/tcp_output.c:918!
invalid operand: 0000 [#1]
CPU:    0
EIP:    0060:[<c027dd56>]    Not tainted VLI
EFLAGS: 00010293   (2.6.13-rc4-endy)
EIP is at tcp_tso_should_defer+0xd6/0xf0
eax: 00000007   ebx: f1258080   ecx: 00000007   edx: f297f800
esi: 00000008   edi: 00000004   ebp: c031fd80   esp: c031fd70
ds: 007b   es: 007b   ss: 0068
Process swapper (pid: 0, threadinfo=c031e000 task=c02dbb80)
Stack: f5f547b8 f1258080 00000008 f297f800 c031fdb8 c027de4b f297f800 
f297f800
        f1258080 00000009 f297f800 d039250c 00000000 00000002 00000002 
f297f800
        f297f800 00000100 c031fddc c027e192 f297f800 00000218 00000001 
f5fd4034
Call Trace:
  [<c0102e5f>] show_stack+0x7f/0xa0
  [<c0103002>] show_registers+0x152/0x1c0
  [<c01031f8>] die+0xc8/0x140
  [<c0103325>] do_trap+0xb5/0xc0
  [<c010366c>] do_invalid_op+0xbc/0xd0
  [<c0102aa3>] error_code+0x4f/0x54
  [<c027de4b>] tcp_write_xmit+0xdb/0x3f0
  [<c027e192>] __tcp_push_pending_frames+0x32/0xd0
  [<c027c04e>] tcp_rcv_state_process+0x2be/0x9c0
  [<c0283ee9>] tcp_v4_do_rcv+0x99/0x120
  [<c02844e2>] tcp_v4_rcv+0x572/0x750
  [<c026a62b>] ip_local_deliver+0xcb/0x1d0
  [<c026aa52>] ip_rcv+0x322/0x4a0
  [<c0256a97>] netif_receive_skb+0x137/0x1a0
  [<c0256b8f>] process_backlog+0x8f/0x110
  [<c0256c82>] net_rx_action+0x72/0x100
  [<c01172dc>] __do_softirq+0x8c/0xa0
  [<c011731a>] do_softirq+0x2a/0x30
  [<c01173d5>] irq_exit+0x35/0x40
  [<c01044fc>] do_IRQ+0x3c/0x70
  [<c0102a46>] common_interrupt+0x1a/0x20
  [<c0100997>] cpu_idle+0x57/0x60
  [<c010024b>] _stext+0x2b/0x30
  [<c0320847>] start_kernel+0x147/0x170
  [<c0100199>] 0xc0100199
Code: 89 f8 0f af c2 3b 45 f0 0f 47 45 f0 31 d2 89 45 f0 f7 f3 31 d2 39 
c1 73 ce ba 01 00 00 00 eb c7 6b c2 03 31 d2 39 c1 77 be eb ee <0f> 0b 
96 03 ae 54 2d c0 e9 76 ff ff ff 8b ba 78 02 00 00 eb eb
  <0>Kernel panic - not syncing: Fatal exception in interrupt

Some infos about my system:

My network card is an e1000.

root # cat /proc/cpuinfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 15
model           : 3
model name      : Intel(R) Pentium(R) 4 CPU 3.00GHz
stepping        : 3
cpu MHz         : 2995.045
cache size      : 1024 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 5
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge 
mca cmov pat pse36 clflush dtsacpi mmx fxsr sse sse2 ss ht tm pbe pni 
monitor ds_cpl cid
bogomips        : 5914.62

http00 root # uname -a
Linux http00 2.6.13-rc4 #1 Thu May 19 14:19:19 CEST 2005 i686 Intel(R) 
Pentium(R) 4 CPU 3.00GHz GenuineIntel GNU/Linux

You can find dmesg, lspci and config at the following address:
http://82.196.5.50/20050731/config.txt
http://82.196.5.50/20050731/dmesg.txt
http://82.196.5.50/20050731/lspci.txt
http://82.196.5.50/20050731/sysctl.txt

Best regards,

Guillaume Pelat

Re: 2.6.13-rc4 - kernel panic - BUG at net/ipv4/tcp_output.c:918

[Andrew Morton]

Guillaume Pelat <guillaume.pelat@winch-hebergement.net> wrote:
>
> Hi,
> 
> Herbert Xu wrote:
> > On Thu, Aug 04, 2005 at 01:33:29PM +1000, herbert wrote:
> > 
> >>So I suppose we should reset cwnd_quota after tcp_transmit_skb?
> > 
> > Please try this patch to see if this is really the problem or not.
> > 
> > Thanks,
> 
> I just applied your patch, and it seems to work :)
> 2 hours uptime, and no crash yet (without the patch, it was crashing a 
> few mins only after booting).
> So i think the bug is crushed :)
> 

Thanks, Guillaume.  Herbert, David is travelling and not able to do a lot
of patchmonkeying.  Could you please prepare and submit a final patch?

Thanks.

Re: 2.6.13-rc4 - kernel panic - BUG at net/ipv4/tcp_output.c:918

[Guillaume Pelat]

Hi,

Herbert Xu wrote:
> On Thu, Aug 04, 2005 at 01:33:29PM +1000, herbert wrote:
> 
>>So I suppose we should reset cwnd_quota after tcp_transmit_skb?
> 
> Please try this patch to see if this is really the problem or not.
> 
> Thanks,

I just applied your patch, and it seems to work :)
2 hours uptime, and no crash yet (without the patch, it was crashing a 
few mins only after booting).
So i think the bug is crushed :)

Thanks a lot !

-- 
Guillaume Pelat

Re: 2.6.13-rc4 - kernel panic - BUG at net/ipv4/tcp_output.c:918

[Herbert Xu]

[-- Attachment #1: Type: text/plain, Size: 413 bytes --]

On Thu, Aug 04, 2005 at 01:33:29PM +1000, herbert wrote:
> 
> So I suppose we should reset cwnd_quota after tcp_transmit_skb?

Please try this patch to see if this is really the problem or not.

Thanks,
-- 
Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <herbert@gondor.apana.org.au>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt

[-- Attachment #2: p --]
[-- Type: text/plain, Size: 674 bytes --]

diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c
--- a/net/ipv4/tcp_output.c
+++ b/net/ipv4/tcp_output.c
@@ -1027,19 +1027,14 @@ static int tcp_write_xmit(struct sock *s
 		tcp_minshall_update(tp, mss_now, skb);
 		sent_pkts++;
 
-		/* Do not optimize this to use tso_segs. If we chopped up
-		 * the packet above, tso_segs will no longer be valid.
-		 */
-		cwnd_quota -= tcp_skb_pcount(skb);
-
-		BUG_ON(cwnd_quota < 0);
-		if (!cwnd_quota)
-			break;
-
 		skb = sk->sk_send_head;
 		if (!skb)
 			break;
+
 		tso_segs = tcp_init_tso_segs(sk, skb, mss_now);
+		cwnd_quota = tcp_cwnd_test(tp, skb);
+		if (!cwnd_quota)
+			break;
 	}
 
 	if (likely(sent_pkts)) {

Re: 2.6.13-rc4 - kernel panic - BUG at net/ipv4/tcp_output.c:918

[Herbert Xu]

On Mon, Aug 01, 2005 at 08:33:20AM +0000, Guillaume Pelat wrote:
> 
> I just tried the patch attached. :)
> 
> The bug is still here (same symptoms), with a slightly different backtrace :
> ------------[ cut here ]------------
> kernel BUG at net/ipv4/tcp_output.c:918!

OK, let's try again :)

I bet it's the tcp_enter_cwr() call in tcp_transmit_skb().  So
the sequence is:

tcp_write_xmit
	cwnd_quota = tcp_cwnd_test
	tcp_transmit_skb
		tcp_enter_cwr
			tp->snd_cwnd = min(tp->snd_cwnd, in_flight + 1)

At this point cwnd_quota is out-of-sync with tp->snd_cwnd.

	cwnd_quota -= tcp_skb_pcount(skb)
	cwnd_quota > 0
	tcp_tso_should_defer
		BUG since tp->snd_cwnd is smaller than what
		cwnd_quota indicated.

So I suppose we should reset cwnd_quota after tcp_transmit_skb?

Perhaps we should only transmit one MSS in this case?

Cheers,
-- 
Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <herbert@gondor.apana.org.au>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt

Re: 2.6.13-rc4 - kernel panic - BUG at net/ipv4/tcp_output.c:918

[Guillaume Pelat]

Hi,

 > [TCP]: Fix two TSO sizing bugs
 >
 > MSS changes can be lost since we preemptively initialize
 > the tso_segs count for an SKB before we %100 commit
 > to sending it out.
 > So, by the time we send it out, the tso_size information
 > can be stale due to PMTU events.  This mucks up all of the
 > logic in our send engine, and can even result in the BUG()
 > triggering in tcp_tso_should_defer().
 > Another problem we have is that we're storing the tp->mss_cache,
 > not the SACK block normalized MSS, as the tso_size.  That's wrong
 > too.
 >
 > Signed-off-by: David S. Miller <davem@davemloft.net>

I just tried the patch attached. :)

The bug is still here (same symptoms), with a slightly different backtrace :
------------[ cut here ]------------
kernel BUG at net/ipv4/tcp_output.c:918!
invalid operand: 0000 [#1]
CPU:    0
EIP:    0060:[<c027dd66>]    Not tainted VLI
EFLAGS: 00010297   (2.6.13-rc4-endy)
EIP is at tcp_tso_should_defer+0xd6/0xf0
eax: 00000005   ebx: f5032e80   ecx: 00000007   edx: f3b2fc00
esi: 00000006   edi: 00000006   ebp: c031fd78   esp: c031fd68
ds: 007b   es: 007b   ss: 0068
Process swapper (pid: 0, threadinfo=c031e000 task=c02dbb80)
Stack: f129b2b8 f5032e80 00000006 f3b2fc00 c031fdb0 c027de7b f3b2fc00 
f3b2fc00
        f5032e80 0000000b f3b2fc00 b7773884 00000000 00000005 00000002 
f3b2fc00
        f3b2fc00 f5a26034 c031fdd4 c027e1b2 f3b2fc00 00000564 00000001 
f5a26034
Call Trace:
  [<c0102e5f>] show_stack+0x7f/0xa0
  [<c0103002>] show_registers+0x152/0x1c0
  [<c01031f8>] die+0xc8/0x140
  [<c0103325>] do_trap+0xb5/0xc0
  [<c010366c>] do_invalid_op+0xbc/0xd0
  [<c0102aa3>] error_code+0x4f/0x54
  [<c027de7b>] tcp_write_xmit+0xfb/0x400
  [<c027e1b2>] __tcp_push_pending_frames+0x32/0xd0
  [<c027b1cc>] tcp_rcv_established+0x27c/0x860 (was 
tcp_rcv_state_process before).
  [<c0283f8a>] tcp_v4_do_rcv+0x11a/0x120
  [<c0284502>] tcp_v4_rcv+0x572/0x750
  [<c026a62b>] ip_local_deliver+0xcb/0x1d0
  [<c026aa52>] ip_rcv+0x322/0x4a0
  [<c0256a97>] netif_receive_skb+0x137/0x1a0
  [<c0256b8f>] process_backlog+0x8f/0x110
  [<c0256c82>] net_rx_action+0x72/0x100
  [<c01172dc>] __do_softirq+0x8c/0xa0
  [<c011731a>] do_softirq+0x2a/0x30
  [<c01173d5>] irq_exit+0x35/0x40
  [<c01044fc>] do_IRQ+0x3c/0x70
  [<c0102a46>] common_interrupt+0x1a/0x20
  [<c0100997>] cpu_idle+0x57/0x60
  [<c010024b>] _stext+0x2b/0x30
  [<c0320847>] start_kernel+0x147/0x170
  [<c0100199>] 0xc0100199
Code: 89 f8 0f af c2 3b 45 f0 0f 47 45 f0 31 d2 89 45 f0 f7 f3 31 d2 39 
c1 73 ce ba 01 00 00 00 eb c7 6b c2 03 31 d239 c1 77 be eb ee <0f> 0b 96 
03 ce 54 2d c0 e9 76 ff ff ff 8b ba 78 02 00 00 eb eb
  <0>Kernel panic - not syncing: Fatal exception in interrupt

I guess it's the same bug :)

Just a few more infos about the problem :
- Turning off TSO with ethtool solves the problem.
- I tried 2.6.13-rc4 on another server (with the same configuration) and 
the bug occured too (so i guess it's not due to some weird memory 
problem :) )
- The problem dont seems to be present in 2.6.12.3 (but i only tried 
2.6.12.3 during 2 days).


Best Regards,

Guillaume Pelat