assertion (cnt <= tp->packets_out) failed

assertion (cnt <= tp->packets_out) failed

[John Bäckstrand]

I get

KERNEL: assertion (cnt <= tp->packets_out) failed at 
net/ipv4/tcp_input.c (1476)

with 2.6.13-rc5, also with a small netpoll patch that shouldnt affect 
these things. (Topic: "lockups with netconsole on e1000 on media 
insertion").

I have a decent amount of dropped/overruns:

eth2      Link encap:Ethernet  HWaddr 00:50:DA:E0:BB:36
           inet addr:83.233.27.60  Bcast:83.233.27.255  Mask:255.255.255.0
           inet6 addr: fe80::250:daff:fee0:bb36/64 Scope:Link
           UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
           RX packets:9141685 errors:0 dropped:0 overruns:794 frame:0
           TX packets:10596040 errors:0 dropped:0 overruns:0 carrier:0
           collisions:0 txqueuelen:1000
           RX bytes:950232746 (906.2 MiB)  TX bytes:804721505 (767.4 MiB)
           Interrupt:10 Base address:0x8800

eth3      Link encap:Ethernet  HWaddr 00:0E:0C:75:F1:2A
           inet addr:10.32.0.1  Bcast:10.255.255.255  Mask:255.255.0.0
           inet6 addr: fe80::20e:cff:fe75:f12a/64 Scope:Link
           UP BROADCAST RUNNING MULTICAST  MTU:16000  Metric:1
           RX packets:16090188 errors:2329 dropped:4658 overruns:2329 
frame:0
           TX packets:34370559 errors:0 dropped:0 overruns:0 carrier:0
           collisions:0 txqueuelen:1000
           RX bytes:1148661167 (1.0 GiB)  TX bytes:4000412315 (3.7 GiB)
           Base address:0x8400 Memory:e2000000-e2020000



ethtool -S eth3
NIC statistics:
      rx_packets: 16195970
      tx_packets: 34563822
      rx_bytes: 1258213074
      tx_bytes: 4205874656
      rx_errors: 2332
      tx_errors: 0
      rx_dropped: 2332
      tx_dropped: 0
      multicast: 0
      collisions: 0
      rx_length_errors: 0
      rx_over_errors: 0
      rx_crc_errors: 0
      rx_frame_errors: 0
      rx_fifo_errors: 2332
      rx_no_buffer_count: 0
      rx_missed_errors: 2332
      tx_aborted_errors: 0
      tx_carrier_errors: 0
      tx_fifo_errors: 0
      tx_heartbeat_errors: 0
      tx_window_errors: 0
      tx_abort_late_coll: 0
      tx_deferred_ok: 0
      tx_single_coll_ok: 0
      tx_multi_coll_ok: 0
      rx_long_length_errors: 0
      rx_short_length_errors: 0
      rx_align_errors: 0
      tx_tcp_seg_good: 2981894
      tx_tcp_seg_failed: 0
      rx_flow_control_xon: 0
      rx_flow_control_xoff: 0
      tx_flow_control_xon: 0
      tx_flow_control_xoff: 0
      rx_long_byte_count: 14143114962
      rx_csum_offload_good: 16195740
      rx_csum_offload_errors: 0


ethtool -S eth2
NIC statistics:
      tx_deferred: 0
      tx_multiple_collisions: 0
      rx_bad_ssd: 0

---
John Bäckstrand

Re: assertion (cnt <= tp->packets_out) failed

[David S. Miller]

From: John Bäckstrand <sandos@home.se>
Date: Fri, 05 Aug 2005 17:53:11 +0200

> KERNEL: assertion (cnt <= tp->packets_out) failed at 
> net/ipv4/tcp_input.c (1476)

I suspect this is a side effect of some changes Herbert Xu and
myself did to fix some other bugs.

Herbert, I think there are serious consequences for changing the
TSO counts for packets we have sent out already.  This mucks up
all of the loss packet counts, which triggers asserts all over
in tcp_input.c

As you may note, we have all of this special code when we fragment
packets that updates all of the counters properly.  And we're
not doing that for the new code that reinits the TSO count when
the MSS is found to no longer match.

It therefore may be desirable to keep Herbert's fix in there, but
back out my changes until they can be reimplemented correctly.

Herbert?

Re: assertion (cnt <= tp->packets_out) failed

[Herbert Xu]

On Fri, Aug 05, 2005 at 09:32:08AM -0700, David S. Miller wrote:
> 
> It therefore may be desirable to keep Herbert's fix in there, but
> back out my changes until they can be reimplemented correctly.
> 
> Herbert?

Sure.  Let's back it out until a better solution is found.
-- 
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: assertion (cnt <= tp->packets_out) failed

[Herbert Xu]

On Sat, Aug 06, 2005 at 12:24:35PM +1000, herbert wrote:
> On Fri, Aug 05, 2005 at 09:32:08AM -0700, David S. Miller wrote:
> > 
> > It therefore may be desirable to keep Herbert's fix in there, but
> > back out my changes until they can be reimplemented correctly.
> > 
> > Herbert?
> 
> Sure.  Let's back it out until a better solution is found.

Hang on a second, the original poster mentioned rc5.  Is this really
pristine rc5 with the one netpoll patch? If so then it can't be the
patches we're talking about because they only went in days later.

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: assertion (cnt <= tp->packets_out) failed

[John Bäckstrand]

> Hang on a second, the original poster mentioned rc5.  Is this really
> pristine rc5 with the one netpoll patch? If so then it can't be the
> patches we're talking about because they only went in days later.

Yes, I have no other patches in, so if it was not in -RC5, I was not 
running it.

---
John Bäckstrand

Re: assertion (cnt <= tp->packets_out) failed

[David S. Miller]

From: Herbert Xu <herbert@gondor.apana.org.au>
Date: Sat, 6 Aug 2005 17:57:17 +1000

> Hang on a second, the original poster mentioned rc5.  Is this really
> pristine rc5 with the one netpoll patch? If so then it can't be the
> patches we're talking about because they only went in days later.

This seems to be confirmed now... so I'll hold off on the revert
for now.

Re: assertion (cnt <= tp->packets_out) failed

[Herbert Xu]

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

On Sat, Aug 06, 2005 at 02:06:53PM +0200, John B?ckstrand wrote:
> 
> Yes, I have no other patches in, so if it was not in -RC5, I was not 
> running it.

OK having looked at it briefly I have a hunch that it may be the
fackets_out issue (when the effective MSS is reduced tcp_tso_acked
may increase fackets_out) I referred to in another thread.

However, I'd like to be more certain as to whether this is the
cause before we do anything.  So please apply this patch and
attempt to reproduce the problem.  It should give us more info
which may help in pin-pointing the problem.

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: 554 bytes --]

diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
--- a/net/ipv4/tcp_input.c
+++ b/net/ipv4/tcp_input.c
@@ -1474,6 +1474,10 @@ static void tcp_mark_head_lost(struct so
 	int cnt = packets;
 
 	BUG_TRAP(cnt <= tp->packets_out);
+	if (unlikely(cnt <= tp->packets_out)) {
+		printk("packets_out = %d, fackets_out = %d, reordering = %d, sack_ok = 0x%x, mss_cache=%d\n", tp->packets_out, tp->fackets_out, tp->reordering, tp->rx_opt.sack_ok, tp->mss_cache);
+		dump_stack();
+	}
 
 	sk_stream_for_retrans_queue(skb, sk) {
 		cnt -= tcp_skb_pcount(skb);

Re: assertion (cnt <= tp->packets_out) failed

[John Bäckstrand]

Someone asked if I could try to trigger this assertion again, and I'm 
afraid I probably cannot, I didnt do anything special at the time. But 
I've got something even better for you all, got a BUG from something 
tcp-related. Mind you, I am trying to find a possibly hardware-related 
issue here, so if this bug does not make any sense it might be my hardware!

I would actually want to know it if this is likely hardware-related or 
not, since I have no idea if its RAM, CPU, motherboard or "only" a disk 
that is broken. I know _something_ is broken, due to lockups, and seeing 
a faulty disk indicated in a HDD diag, but only once, the disk is 
apparently fine 99% of the time.

---
John Bäckstrand


[148475.651000] ------------[ cut here ]------------
[148475.651050] kernel BUG at net/ipv4/tcp_output.c:918!
[148475.651078] invalid operand: 0000 [#1]
[148475.651103] Modules linked in: sha256 aes_i586 dm_crypt ipt_state 
ipt_multiport ipt_MASQUERADE iptable_filter netconsole md5 ipv6 
af_packet pdc202xx_new e1000 8139cp de2104x i2c_viapro via686a 
i2c_sensor i2c_core uhci_hcd usbcore 3c59x 8139too mii de4x5 crc32 
parport_pc parport reiserfs dm_mod ip_nat_ftp iptable_nat ip_tables 
ip_conntrack_ftp ip_conntrack rtc unix
[148475.651378] CPU:    0
[148475.651380] EIP:    0060:[<c0286619>]    Not tainted VLI
[148475.651383] EFLAGS: 00010287   (2.6.13-rc5sand4)
[148475.651464] EIP is at tcp_tso_should_defer+0xc9/0xe0
[148475.651494] eax: 0000002b   ebx: ce49a660   ecx: 0000002c   edx: 
ca008d00
[148475.651526] esi: 0000002c   edi: 0000000e   ebp: 99d57104   esp: 
c0865dec
[148475.651556] ds: 007b   es: 007b   ss: 0068
[148475.651582] Process tor (pid: 10849, threadinfo=c0864000 task=c6234530)
[148475.651602] Stack: ce49a660 0000002c ca008d00 99d57104 c02866fc 
ca008d00 ca008d00 ce49a660
[148475.651676]        0000003a 00000102 0000000e 00000001 ca008d00 
ca008d00 ca008d00 c9290034
[148475.651751]        c0286a49 ca008d00 000005b4 00000001 c0254674 
81dd5b2f 81dd5b2f 00000010
[148475.651823] Call Trace:
[148475.651869]  [<c02866fc>] tcp_write_xmit+0xcc/0x3e0
[148475.651910]  [<c0286a49>] __tcp_push_pending_frames+0x39/0xd0
[148475.651947]  [<c0254674>] kfree_skbmem+0x24/0x30
[148475.651988]  [<c0283bbe>] tcp_rcv_established+0x26e/0x840
[148475.652033]  [<c028c935>] tcp_v4_do_rcv+0x115/0x120
[148475.652072]  [<c028cf8f>] tcp_v4_rcv+0x64f/0x890
[148475.652106]  [<c02735b0>] ip_local_deliver_finish+0x0/0x1c0
[148475.652150]  [<c0265a6e>] nf_hook_slow+0x6e/0x100
[148475.652199]  [<c0272f63>] ip_local_deliver+0xe3/0x250
[148475.652234]  [<c02735b0>] ip_local_deliver_finish+0x0/0x1c0
[148475.652272]  [<c0273425>] ip_rcv+0x355/0x4e0
[148475.652309]  [<c0273770>] ip_rcv_finish+0x0/0x290
[148475.652347]  [<c0259f11>] netif_receive_skb+0x1f1/0x270
[148475.652394]  [<c025a00f>] process_backlog+0x7f/0x100
[148475.652431]  [<c025a10a>] net_rx_action+0x7a/0x120
[148475.652467]  [<c011b9bd>] __do_softirq+0x7d/0x90
[148475.652509]  [<c011b9f6>] do_softirq+0x26/0x30
[148475.652544]  [<c010561e>] do_IRQ+0x1e/0x30
[148475.652588]  [<c0103a92>] common_interrupt+0x1a/0x20
[148475.652630] Code: db 74 1d 89 f8 0f af c2 39 f0 0f 46 f0 31 d2 89 f0 
f7 f3 31 d2 39 c1 73 cb ba 01 00 00 00 eb c4 6b c2 03 31 d2 39 c1 77 bb 
eb ee <0f> 0b 96 03 20 2f 2e c0 eb 83 8b ba 7c 02 00 00 eb ee 90 8d 74
[148475.653330]  <0>Kernel panic - not syncing: Fatal exception in interrupt

Re: assertion (cnt <= tp->packets_out) failed

[Andrew Morton]

John Bäckstrand <sandos@home.se> wrote:
>
>  Someone asked if I could try to trigger this assertion again, and I'm 
>  afraid I probably cannot, I didnt do anything special at the time. But 
>  I've got something even better for you all, got a BUG from something 
>  tcp-related. Mind you, I am trying to find a possibly hardware-related 
>  issue here, so if this bug does not make any sense it might be my hardware!
> 
>  I would actually want to know it if this is likely hardware-related or 
>  not, since I have no idea if its RAM, CPU, motherboard or "only" a disk 
>  that is broken. I know _something_ is broken, due to lockups, and seeing 
>  a faulty disk indicated in a HDD diag, but only once, the disk is 
>  apparently fine 99% of the time.
> 
>  ---
>  John Bäckstrand
> 
> 
>  [148475.651000] ------------[ cut here ]------------
>  [148475.651050] kernel BUG at net/ipv4/tcp_output.c:918!

I think we've seen a couple of reports of this.

>  [148475.651078] invalid operand: 0000 [#1]
>  [148475.651103] Modules linked in: sha256 aes_i586 dm_crypt ipt_state 
>  ipt_multiport ipt_MASQUERADE iptable_filter netconsole md5 ipv6 
>  af_packet pdc202xx_new e1000 8139cp de2104x i2c_viapro via686a 
>  i2c_sensor i2c_core uhci_hcd usbcore 3c59x 8139too mii de4x5 crc32 
>  parport_pc parport reiserfs dm_mod ip_nat_ftp iptable_nat ip_tables 
>  ip_conntrack_ftp ip_conntrack rtc unix
>  [148475.651378] CPU:    0
>  [148475.651380] EIP:    0060:[<c0286619>]    Not tainted VLI
>  [148475.651383] EFLAGS: 00010287   (2.6.13-rc5sand4)

Can you tell us exactly which kernel this is based on?  If it's 2.6.13-rc5
then it would be better to be testing 2.6.13-rc5-git<latest>, because some
net fixes have been recently merged.

Re: assertion (cnt <= tp->packets_out) failed

[Herbert Xu]

On Sun, Aug 07, 2005 at 03:25:55PM +0200, John B?ckstrand wrote:
> 
> [148475.651000] ------------[ cut here ]------------
> [148475.651050] kernel BUG at net/ipv4/tcp_output.c:918!

Yes, as Andrew said, this bug should be fixed in the latest git tree.
So please test with that plus the debugging patch to see if you can
reproduce the assertion again.

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

Re: assertion (cnt <= tp->packets_out) failed

[Heikki Orsila]

Heikki Orsila wrote:
> There were big changes in tcp_output.c between rc1 and rc2, and the 
> bug is triggered when using e1000 with rc2 or later. And because the 
> bug does not happen on skge (new sk98 driver) it makes me guess it's a 
> race condition of sorts.. I am surprised this bug wasn't noticed with 
> rc2.

One more bit of info: there was no e1000 driver changes between rc1 and 
rc2, which increases the evidence that the error was induced by
tcp_output.c.

-- 
Heikki Orsila			Barbie's law:
heikki.orsila@iki.fi		"Math is hard, let's go shopping!"
http://www.iki.fi/shd

Re: assertion (cnt <= tp->packets_out) failed

[Heikki Orsila]

Herbert Xu <herbert@gondor.apana.org.au> wrote:
> Hang on a second, the original poster mentioned rc5.  Is this really
> pristine rc5 with the one netpoll patch? If so then it can't be the
> patches we're talking about because they only went in days later.

I produced a similar panic on rc2 and later (which doesn't happen on 
rc1). See my other post in this thread.

-- 
Heikki Orsila			Barbie's law:
heikki.orsila@iki.fi		"Math is hard, let's go shopping!"
http://www.iki.fi/shd

Re: assertion (cnt <= tp->packets_out) failed

[Heikki Orsila]

David S. Miller wrote:
> I suspect this is a side effect of some changes Herbert Xu and 
> myself did to fix some other bugs.

I think I crossed this bug independently today. I did some testing, and 
got kernel panics when uploading files with ftp on a gigabit lan. The 
error happens always at net/ipv4/tcp_output.c:918. Here's a matrix of 
combinations that crashes or doesn't crash:

kernel			what happens
2.6.12			no crash
2.6.13-rc1 & e1000	no crash
2.6.13-rc1 & skge	no crash
2.6.13-rc2 & e1000	crash
2.6.13-rc2 & skge	no crash
2.6.13-rc3 & e1000	crash
2.6.13-rc3 & skge	no crash
2.6.13-rc5 & e1000	crash
2.6.13-rc5 & skge	no crash

There were big changes in tcp_output.c between rc1 and rc2, and the bug 
is triggered when using e1000 with rc2 or later. And because the bug 
does not happen on skge (new sk98 driver) it makes me guess it's a race 
condition of sorts.. I am surprised this bug wasn't noticed with rc2.

The crash happens just in the beginning of a tcp connection. Only some 
packets are sent and then the sends stall by slowing down, and after 5 
secs the kernel crashes. Basically usage pattern is this:

upload file a
upload file b
upload file a (replaces old file)
upload file b (replaces old file)
upload file a (replaces old file) => slowdown and then a crash in 5 secs 


Here's the kernel greeting:

Kernel BUG at "net/ipv4/tcp_output.c":918
Invalid operand: 0000 [1]
CPU 0
Modules linked in:
Pid 0, comm: swapper Not tainted 2.6.13-rc5
RIP: 0010:[<ffffffff804d086d>] <ffffffff804d086d><__tcp_push_pending_frames+429>
...
Process swapper (pid: 0, threadinfo ffffffff807de000, task ffffffff80640ec0)
...
Call Trace: <IRQ> <ffffffff804ce30c><tcp_rcv_established+1964>
		  <...>             <tcp_v4_do_rcv+37> ... <...><ip_local_deliver_finish+0>
		  <...>             <tcp_v4_rcv+1483> ... <...><ip_local_deliver+322>
		  <...>             <ip_rcv+1107> ... <...><netif_receive_skb+426>
		  <...>             <process_backlog+154>
		  <...>             <__do_softirq+83>
		  <...>             <do_softirq+53>
		  <...>             <ret_from_intr+0>
		  <...>             <default_idle+0>
		  <...>             <cpu_idle+49>
		  <...>             <_sinittext+534>
		  <...>             <>
		  <...>             <>
		  <...>             <>
		  <...>             <>
		  <...>             <>
		  <...>             <>
...
RIP <ffffffff804d086d><__tcp_push_pending_frames+429> ...
 <0>Kernel panic - not syncing: Aiee, killing interrupt handler!


Here's system info:

Linux e275d 2.6.13-rc2 #1 Sun Aug 7 18:48:05 EEST 2005 x86_64 AMD Athlon(tm) 64 Processor 3000+ AuthenticAMD GNU/Linux
 
Gnu C                  3.4.3
Gnu make               3.80
binutils               2.15.92.0.2
util-linux             2.12i
mount                  2.12i
module-init-tools      3.0
e2fsprogs              1.38
jfsutils               1.1.4
reiserfsprogs          line
reiser4progs           line
xfsprogs               2.6.25
nfs-utils              1.0.6
Linux C Library        2.3.5
Dynamic linker (ldd)   2.3.5
Procps                 3.2.5
Net-tools              1.60
Kbd                    1.12
Sh-utils               5.2.1
udev                   058
Modules Loaded         



-- 
Heikki Orsila			Barbie's law:
heikki.orsila@iki.fi		"Math is hard, let's go shopping!"
http://www.iki.fi/shd