kernel 2.6.23.8: KERNEL: assertion in net/ipv4/tcp_input.c

kernel 2.6.23.8: KERNEL: assertion in net/ipv4/tcp_input.c

[Wolfgang Walter]

Hello,

with kernel 2.6.23.8 we saw a

KERNEL: assertion ((int)tcp_packets_in_flight(tp) >= 0) failed at 
net/ipv4/tcp_input.c (1292)

Regards,

Wolfgang Walter
-- 
Wolfgang Walter
Studentenwerk München
Anstalt des öffentlichen Rechts

Re: kernel 2.6.23.8: KERNEL: assertion in net/ipv4/tcp_input.c

[Ilpo Järvinen]

On Mon, 3 Dec 2007, Wolfgang Walter wrote:

> with kernel 2.6.23.8 we saw a
> 
> KERNEL: assertion ((int)tcp_packets_in_flight(tp) >= 0) failed at 
> net/ipv4/tcp_input.c (1292)

Is this the only message? Are there any Leak printouts?
Any tweaking done to TCP related sysctls?
And for completeness, is GSO enabled (ethtool -k)?

Most likely I broke the manual synchronization for left_out in sacktag by 
skipping over it when packets_out == 0 but so far I haven't been able to 
figure out how such state could develop in the first place... Ie., I 
couldn't find a case where tcp_fastretrans_alert wouldn't be called if 
left_out was non-zero (and it did the sync_left_out after modifying
either sacked_out or lost_out, IIRC).

...If you can reproduce it, you could try if this patch below changes 
anything (should silence the assert and trigger earlier a WARN_ON or
two :-)). ...If this triggers, then I'm sure we can pollute TCP code
by a larger number of more costly checks to catch it in early.

This might reveal a long-standing inconsistency of left_out in some
case I just couldn't come up with by code review. Left_out will be
(is) anyway dropped as unnecessary in 2.6.24. In 2.6.23 sync for
left_out occurs quite soon after that BUG_TRAP anyway so the effect
won't be too dramatic, prior_in_flight would be once stale, won't
lead to big problems (either missed cnwd or cwnd_cnt increment, or
failure to do application limited check at that particular ACK).

Thanks anyway for the report. ...If I figure something out here, I'll
let you know.

--

diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
index c9298a7..0c5194d 100644
--- a/net/ipv4/tcp_input.c
+++ b/net/ipv4/tcp_input.c
@@ -1012,8 +1012,12 @@ tcp_sacktag_write_queue(struct sock *sk, struct sk_buff *ack_skb, u32 prior_snd_
 	if (before(TCP_SKB_CB(ack_skb)->ack_seq, prior_snd_una - tp->max_window))
 		return 0;
 
-	if (!tp->packets_out)
+	if (!tp->packets_out) {
+		WARN_ON(tp->sacked_out);
+		WARN_ON(tp->lost_out);
+		WARN_ON(tp->left_out);
 		goto out;
+	}
 
 	/* SACK fastpath:
 	 * if the only SACK change is the increase of the end_seq of
@@ -1277,14 +1281,14 @@ tcp_sacktag_write_queue(struct sock *sk, struct sk_buff *ack_skb, u32 prior_snd_
 		}
 	}
 
+out:
+
 	tp->left_out = tp->sacked_out + tp->lost_out;
 
 	if ((reord < tp->fackets_out) && icsk->icsk_ca_state != TCP_CA_Loss &&
 	    (!tp->frto_highmark || after(tp->snd_una, tp->frto_highmark)))
 		tcp_update_reordering(sk, ((tp->fackets_out + 1) - reord), 0);
 
-out:
-
 #if FASTRETRANS_DEBUG > 0
 	BUG_TRAP((int)tp->sacked_out >= 0);
 	BUG_TRAP((int)tp->lost_out >= 0);

Re: kernel 2.6.23.8: KERNEL: assertion in net/ipv4/tcp_input.c

[Wolfgang Walter]

Am Montag, 3. Dezember 2007 14:34 schrieb Ilpo Järvinen:
> On Mon, 3 Dec 2007, Wolfgang Walter wrote:
> > with kernel 2.6.23.8 we saw a
> >
> > KERNEL: assertion ((int)tcp_packets_in_flight(tp) >= 0) failed at
> > net/ipv4/tcp_input.c (1292)
>
> Is this the only message? Are there any Leak printouts?

No.

4 days earlier there were 3 messages: TCP: Treason uncloaked! Peer 
a.b.c.d:80/56532 shrinks window 3535507131:3535513869. Repaired.

> Any tweaking done to TCP related sysctls?
> And for completeness, is GSO enabled (ethtool -k)?

rx-checksumming: on
tx-checksumming: on
scatter-gather: on
tcp segmentation offload: off
udp fragmentation offload: off
generic segmentation offload: off

>
> Most likely I broke the manual synchronization for left_out in sacktag by
> skipping over it when packets_out == 0 but so far I haven't been able to
> figure out how such state could develop in the first place... Ie., I
> couldn't find a case where tcp_fastretrans_alert wouldn't be called if
> left_out was non-zero (and it did the sync_left_out after modifying
> either sacked_out or lost_out, IIRC).
>
> ...If you can reproduce it, you could try if this patch below changes

I don't know how to reproduce it - we never saw the message before. I'll aply 
the patch. Let see if the WARN_ON triggers before we update to a newer 
kernel :-).

> anything (should silence the assert and trigger earlier a WARN_ON or
> two :-)). ...If this triggers, then I'm sure we can pollute TCP code
> by a larger number of more costly checks to catch it in early.
>
> This might reveal a long-standing inconsistency of left_out in some
> case I just couldn't come up with by code review. Left_out will be
> (is) anyway dropped as unnecessary in 2.6.24. In 2.6.23 sync for
> left_out occurs quite soon after that BUG_TRAP anyway so the effect
> won't be too dramatic, prior_in_flight would be once stale, won't
> lead to big problems (either missed cnwd or cwnd_cnt increment, or
> failure to do application limited check at that particular ACK).
>
> Thanks anyway for the report. ...If I figure something out here, I'll
> let you know.
>
> --
>
> diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
> index c9298a7..0c5194d 100644
> --- a/net/ipv4/tcp_input.c
> +++ b/net/ipv4/tcp_input.c
> @@ -1012,8 +1012,12 @@ tcp_sacktag_write_queue(struct sock *sk, struct
> sk_buff *ack_skb, u32 prior_snd_ if (before(TCP_SKB_CB(ack_skb)->ack_seq,
> prior_snd_una - tp->max_window)) return 0;
>
> -	if (!tp->packets_out)
> +	if (!tp->packets_out) {
> +		WARN_ON(tp->sacked_out);
> +		WARN_ON(tp->lost_out);
> +		WARN_ON(tp->left_out);
>  		goto out;
> +	}
>
>  	/* SACK fastpath:
>  	 * if the only SACK change is the increase of the end_seq of
> @@ -1277,14 +1281,14 @@ tcp_sacktag_write_queue(struct sock *sk, struct
> sk_buff *ack_skb, u32 prior_snd_ }
>  	}
>
> +out:
> +
>  	tp->left_out = tp->sacked_out + tp->lost_out;
>
>  	if ((reord < tp->fackets_out) && icsk->icsk_ca_state != TCP_CA_Loss &&
>  	    (!tp->frto_highmark || after(tp->snd_una, tp->frto_highmark)))
>  		tcp_update_reordering(sk, ((tp->fackets_out + 1) - reord), 0);
>
> -out:
> -
>  #if FASTRETRANS_DEBUG > 0
>  	BUG_TRAP((int)tp->sacked_out >= 0);
>  	BUG_TRAP((int)tp->lost_out >= 0);

Thanks and regards,
-- 
Wolfgang Walter
Studentenwerk München
Anstalt des öffentlichen Rechts

Re: kernel 2.6.23.8: KERNEL: assertion in net/ipv4/tcp_input.c

[Wolfgang Walter]

Hello Ilpo,

it happened again with your patch applied:

WARNING: at net/ipv4/tcp_input.c:1018 tcp_sacktag_write_queue()

Call Trace:
<IRQ>  [<ffffffff80549290>] tcp_sacktag_write_queue+0x7d0/0xa60
[<ffffffff80283869>] add_partial+0x19/0x60
[<ffffffff80549ac4>] tcp_ack+0x5a4/0x1d70
[<ffffffff8054e625>] tcp_rcv_established+0x485/0x7b0
[<ffffffff80554c3d>] tcp_v4_do_rcv+0xed/0x3e0
[<ffffffff80556fe7>] tcp_v4_rcv+0x947/0x970
[<ffffffff80538c6c>] ip_local_deliver+0xac/0x290
[<ffffffff80538862>] ip_rcv+0x362/0x6c0
[<ffffffff804fc5d3>] netif_receive_skb+0x323/0x420
[<ffffffff8042ab40>] tg3_poll+0x630/0xa50
[<ffffffff804fecba>] net_rx_action+0x8a/0x140
[<ffffffff8023a269>] __do_softirq+0x69/0xe0
[<ffffffff8020d47c>] call_softirq+0x1c/0x30
[<ffffffff8020f315>] do_softirq+0x35/0x90
[<ffffffff8023a105>] irq_exit+0x55/0x60
[<ffffffff8020f3f0>] do_IRQ+0x80/0x100
[<ffffffff8020c7d1>] ret_from_intr+0x0/0xa
<EOI>


Am Montag, 3. Dezember 2007 14:34 schrieb Ilpo Järvinen:
> On Mon, 3 Dec 2007, Wolfgang Walter wrote:
> > with kernel 2.6.23.8 we saw a
> >
> > KERNEL: assertion ((int)tcp_packets_in_flight(tp) >= 0) failed at
> > net/ipv4/tcp_input.c (1292)
>
> Is this the only message? Are there any Leak printouts?
> Any tweaking done to TCP related sysctls?

net/core/somaxconn=2048
net/ipv4/tcp_syncookies=1
net/ipv4/tcp_max_syn_backlog=8192
net/ipv4/tcp_max_tw_buckets=1800000
net/ipv4/tcp_window_scaling=0
net/ipv4/tcp_timestamps=0

>
> Most likely I broke the manual synchronization for left_out in sacktag by
> skipping over it when packets_out == 0 but so far I haven't been able to
> figure out how such state could develop in the first place... Ie., I
> couldn't find a case where tcp_fastretrans_alert wouldn't be called if
> left_out was non-zero (and it did the sync_left_out after modifying
> either sacked_out or lost_out, IIRC).
>
> ...If you can reproduce it, you could try if this patch below changes
> anything (should silence the assert and trigger earlier a WARN_ON or
> two :-)). ...If this triggers, then I'm sure we can pollute TCP code
> by a larger number of more costly checks to catch it in early.
>
> This might reveal a long-standing inconsistency of left_out in some
> case I just couldn't come up with by code review. Left_out will be
> (is) anyway dropped as unnecessary in 2.6.24. In 2.6.23 sync for
> left_out occurs quite soon after that BUG_TRAP anyway so the effect
> won't be too dramatic, prior_in_flight would be once stale, won't
> lead to big problems (either missed cnwd or cwnd_cnt increment, or
> failure to do application limited check at that particular ACK).
>
> Thanks anyway for the report. ...If I figure something out here, I'll
> let you know.
>
> --
>
> diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
> index c9298a7..0c5194d 100644
> --- a/net/ipv4/tcp_input.c
> +++ b/net/ipv4/tcp_input.c
> @@ -1012,8 +1012,12 @@ tcp_sacktag_write_queue(struct sock *sk, struct
> sk_buff *ack_skb, u32 prior_snd_ if (before(TCP_SKB_CB(ack_skb)->ack_seq,
> prior_snd_una - tp->max_window)) return 0;
>
> -	if (!tp->packets_out)
> +	if (!tp->packets_out) {
> +		WARN_ON(tp->sacked_out);
> +		WARN_ON(tp->lost_out);
> +		WARN_ON(tp->left_out);
>  		goto out;
> +	}
>
>  	/* SACK fastpath:
>  	 * if the only SACK change is the increase of the end_seq of
> @@ -1277,14 +1281,14 @@ tcp_sacktag_write_queue(struct sock *sk, struct
> sk_buff *ack_skb, u32 prior_snd_ }
>  	}
>
> +out:
> +
>  	tp->left_out = tp->sacked_out + tp->lost_out;
>
>  	if ((reord < tp->fackets_out) && icsk->icsk_ca_state != TCP_CA_Loss &&
>  	    (!tp->frto_highmark || after(tp->snd_una, tp->frto_highmark)))
>  		tcp_update_reordering(sk, ((tp->fackets_out + 1) - reord), 0);
>
> -out:
> -
>  #if FASTRETRANS_DEBUG > 0
>  	BUG_TRAP((int)tp->sacked_out >= 0);
>  	BUG_TRAP((int)tp->lost_out >= 0);

Regards,
-- 
Wolfgang Walter
Studentenwerk München
Anstalt des öffentlichen Rechts

Re: kernel 2.6.23.8: KERNEL: assertion in net/ipv4/tcp_input.c

[Ilpo Järvinen]

On Thu, 13 Dec 2007, Wolfgang Walter wrote:

> it happened again with your patch applied:
> 
> WARNING: at net/ipv4/tcp_input.c:1018 tcp_sacktag_write_queue()
> 
> Call Trace:
> <IRQ>  [<ffffffff80549290>] tcp_sacktag_write_queue+0x7d0/0xa60
> [<ffffffff80283869>] add_partial+0x19/0x60
> [<ffffffff80549ac4>] tcp_ack+0x5a4/0x1d70
> [<ffffffff8054e625>] tcp_rcv_established+0x485/0x7b0
> [<ffffffff80554c3d>] tcp_v4_do_rcv+0xed/0x3e0
> [<ffffffff80556fe7>] tcp_v4_rcv+0x947/0x970
> [<ffffffff80538c6c>] ip_local_deliver+0xac/0x290
> [<ffffffff80538862>] ip_rcv+0x362/0x6c0
> [<ffffffff804fc5d3>] netif_receive_skb+0x323/0x420
> [<ffffffff8042ab40>] tg3_poll+0x630/0xa50
> [<ffffffff804fecba>] net_rx_action+0x8a/0x140
> [<ffffffff8023a269>] __do_softirq+0x69/0xe0
> [<ffffffff8020d47c>] call_softirq+0x1c/0x30
> [<ffffffff8020f315>] do_softirq+0x35/0x90
> [<ffffffff8023a105>] irq_exit+0x55/0x60
> [<ffffffff8020f3f0>] do_IRQ+0x80/0x100
> [<ffffffff8020c7d1>] ret_from_intr+0x0/0xa
> <EOI>

...Yeah, as I suspected, left_out != 0 when sacked_out and lost_out are 
zero. I'll try to read the code again to see how that could happen (in 
any case this is just annoying at the best, no other harm but the 
message is being done). ...If nothing comes up I might ask you to run
with another test patch but it might take week or so until I've enough
time to dig into this fully because I must also come familiar with 
something as pre-historic as the 2.6.23 (there are already large number
of related changes since then, both in upcoming 2.6.24 and some in 
net-2.6.25)... :-)

> > Any tweaking done to TCP related sysctls?
> 
> net/core/somaxconn=2048
> net/ipv4/tcp_syncookies=1
> net/ipv4/tcp_max_syn_backlog=8192
> net/ipv4/tcp_max_tw_buckets=1800000
> net/ipv4/tcp_window_scaling=0
> net/ipv4/tcp_timestamps=0

Thanks, these won't be that significant, though timestamps will exclude 
some possibilities :-).


-- 
 i.

Re: kernel 2.6.23.8: KERNEL: assertion in net/ipv4/tcp_input.c

[Ilpo Järvinen]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 3936 bytes --]

On Fri, 14 Dec 2007, Ilpo Järvinen wrote:

> On Thu, 13 Dec 2007, Wolfgang Walter wrote:
> 
> > it happened again with your patch applied:
> > 
> > WARNING: at net/ipv4/tcp_input.c:1018 tcp_sacktag_write_queue()
> > 
> > Call Trace:
> > <IRQ>  [<ffffffff80549290>] tcp_sacktag_write_queue+0x7d0/0xa60
> > [<ffffffff80283869>] add_partial+0x19/0x60
> > [<ffffffff80549ac4>] tcp_ack+0x5a4/0x1d70
> > [<ffffffff8054e625>] tcp_rcv_established+0x485/0x7b0
> > [<ffffffff80554c3d>] tcp_v4_do_rcv+0xed/0x3e0
> > [<ffffffff80556fe7>] tcp_v4_rcv+0x947/0x970
> > [<ffffffff80538c6c>] ip_local_deliver+0xac/0x290
> > [<ffffffff80538862>] ip_rcv+0x362/0x6c0
> > [<ffffffff804fc5d3>] netif_receive_skb+0x323/0x420
> > [<ffffffff8042ab40>] tg3_poll+0x630/0xa50
> > [<ffffffff804fecba>] net_rx_action+0x8a/0x140
> > [<ffffffff8023a269>] __do_softirq+0x69/0xe0
> > [<ffffffff8020d47c>] call_softirq+0x1c/0x30
> > [<ffffffff8020f315>] do_softirq+0x35/0x90
> > [<ffffffff8023a105>] irq_exit+0x55/0x60
> > [<ffffffff8020f3f0>] do_IRQ+0x80/0x100
> > [<ffffffff8020c7d1>] ret_from_intr+0x0/0xa
> > <EOI>
> 
> ...Yeah, as I suspected, left_out != 0 when sacked_out and lost_out are 
> zero. I'll try to read the code again to see how that could happen (in 
> any case this is just annoying at the best, no other harm but the 
> message is being done). ...If nothing comes up I might ask you to run
> with another test patch but it might take week or so until I've enough
> time to dig into this fully because I must also come familiar with 
> something as pre-historic as the 2.6.23 (there are already large number
> of related changes since then, both in upcoming 2.6.24 and some in 
> net-2.6.25)... :-)

...I checked and found this one place from where left_out inconsistency 
could develop from in stable-2.6.23 or earlier. No idea though how we end 
up there and do not sync afterwards. Adding WARN_ON to that branch might 
help but it will give false positives too from sacktag_write_queue
due to DSACKs. 

...If either of you wants to, you could add WARN_ON(1) to that modified 
block too and just ignore those now and then stack_traces having
tcp_sacktag_write_queue calling tcp_fragment (they are not suspect because 
they occur due to DSACKs and sync before the assertion).

-- 
 i.

--
[PATCH] [TCP]: Try to fix left_out inconsistency

This spot performs (ie., doesn't perform it) obviously incorrect
counting for left_out though I know very few ways to call
tcp_fragment() for SACKED_ACKED skbs (DSACK seems to be the only
case, and perhaps some split-after-first ACK SACK blocks could
cause this as well and both fill sync after the loop). Those
usually shouldn't lead to any adjustments of pcount though (and 
tcp_sync_left_out()s are all over the code so it's very narrow
maze to not "hit" them in between which could remove all temporal 
inconsistencies). Therefore this might not be the actually cause
of the detected inconsistencies but due to complexity of
corner-case  scenarios it seems still be a worth of try (I might
have missed some path :-)).

This is only valid for stable-2.6.23 or earlier because
anything before that drops left_out and calculates it on
the fly from lost_out and sacked_out and is therefore always
consistently in sync.

Signed-off-by: Ilpo Järvinen <ilpo.jarvinen@helsinki.fi>
---
 net/ipv4/tcp_output.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c
index 666d8a5..9fc08cb 100644
--- a/net/ipv4/tcp_output.c
+++ b/net/ipv4/tcp_output.c
@@ -677,8 +677,10 @@ int tcp_fragment(struct sock *sk, struct sk_buff *skb, u32 len, unsigned int mss
 
 		tp->packets_out -= diff;
 
-		if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED)
+		if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED) {
 			tp->sacked_out -= diff;
+			tp->left_out -= diff;
+		}
 		if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_RETRANS)
 			tp->retrans_out -= diff;
 
-- 
1.5.0.6