2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150() - Kernel

This is a discussion on 2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150() - Kernel ; trying to download things, I am seeing this (ignore the tainted, it is from madwifi and although the module is loaded the device was never used) Could anyone make sense of this please? Thanks, Soeren ------------[ cut here ]------------ WARNING: ...

+ Reply to Thread
Results 1 to 8 of 8

Thread: 2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

  1. 2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

    trying to download things, I am seeing this (ignore the tainted, it is
    from madwifi and although the module is loaded the device was never
    used)

    Could anyone make sense of this please?

    Thanks,
    Soeren

    ------------[ cut here ]------------
    WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()
    Modules linked in: vfat fat isofs udf usb_storage coretemp rfcomm l2cap
    hci_usb bluetooth xfrm_user xfrm4_tunnel tunnel4 ipcomp esp4 ah4 hfsplus
    binfmt_misc fuse ebtable_broute bridge llc ebtable_nat ebt
    Pid: 0, comm: swapper Tainted: P 2.6.25-rc8-sonne #24
    [] warn_on_slowpath+0x54/0x70
    [] ? ip_output+0x75/0xd0
    [] ? ip_local_out+0x18/0x20
    [] ? ip_queue_xmit+0x1d4/0x3a0
    [] ? enqueue_task_fair+0x37/0x2a0
    [] ? __skb_clone+0x22/0xd0
    [] tcp_mark_head_lost+0x11d/0x150
    [] ? tcp_transmit_skb+0x410/0x7b0
    [] tcp_ack+0x171b/0x1d60
    [] ? dma_pool_alloc+0xfa/0x1a0
    [] tcp_rcv_established+0x504/0x750
    [] tcp_v4_do_rcv+0xb3/0x1f0
    [] ? __inet_lookup_established+0x17e/0x190
    [] tcp_v4_rcv+0x6bf/0x7c0
    [] ip_local_deliver_finish+0xa9/0x210
    [] ip_local_deliver+0x30/0xa0
    [] ip_rcv_finish+0xff/0x390
    [] ? nf_hook_slow+0xa0/0xf0
    [] ? ip_rcv_finish+0x0/0x390
    [] ip_rcv+0x1e0/0x290
    [] ? ip_rcv_finish+0x0/0x390
    [] ? ip_rcv+0x0/0x290
    [] netif_receive_skb+0x247/0x2d0
    [] sky2_poll+0x4ba/0xc20 [sky2]
    [] ? tick_program_event+0x42/0x70
    [] ? tick_program_event+0x42/0x70
    [] net_rx_action+0xa8/0x130
    [] __do_softirq+0x84/0x100
    [] do_softirq+0x3b/0x50
    [] irq_exit+0x75/0x90
    [] do_IRQ+0x45/0x80
    [] common_interrupt+0x23/0x28
    [] ? acpi_idle_enter_bm+0x28a/0x2f8
    [] cpuidle_idle_call+0x76/0xb0
    [] ? cpuidle_idle_call+0x0/0xb0
    [] cpu_idle+0x6f/0x110
    [] rest_init+0x5d/0x60
    =======================
    ---[ end trace a109db92c4e172c2 ]---
    ------------[ cut here ]------------


    ------------[ cut here ]------------
    WARNING: at net/ipv4/tcp_input.c:1771 tcp_enter_frto+0x267/0x270()
    Modules linked in: vfat fat isofs udf usb_storage coretemp rfcomm l2cap
    hci_usb bluetooth xfrm_user xfrm4_tunnel tunnel4 ipcomp esp4 ah4 hfsplus
    binfmt_misc fuse ebtable_broute bridge llc ebtable_nat ebt
    Pid: 0, comm: swapper Tainted: P 2.6.25-rc8-sonne #24
    [] warn_on_slowpath+0x54/0x70
    [] ? enqueue_task+0x57/0x70
    [] ? __update_rq_clock+0x22/0x180
    [] ? read_hpet+0xd/0x20
    [] ? getnstimeofday+0x34/0xe0
    [] ? ktime_get_ts+0x48/0x50
    [] ? ktime_get+0x19/0x40
    [] tcp_enter_frto+0x267/0x270
    [] tcp_write_timer+0x301/0x690
    [] ? hpet_legacy_next_event+0x29/0x40
    [] ? clockevents_program_event+0x99/0x120
    [] run_timer_softirq+0x155/0x1c0
    [] ? tcp_write_timer+0x0/0x690
    [] ? _spin_unlock+0x1c/0x30
    [] ? tcp_write_timer+0x0/0x690
    [] __do_softirq+0x84/0x100
    [] do_softirq+0x3b/0x50
    [] irq_exit+0x75/0x90
    [] do_IRQ+0x45/0x80
    [] common_interrupt+0x23/0x28
    [] ? acpi_idle_enter_bm+0x28a/0x2f8
    [] cpuidle_idle_call+0x76/0xb0
    [] ? cpuidle_idle_call+0x0/0xb0
    [] cpu_idle+0x6f/0x110
    [] rest_init+0x5d/0x60
    =======================
    ---[ end trace a109db92c4e172c2 ]---
    ------------[ cut here ]------------


    ------------[ cut here ]------------
    WARNING: at net/ipv4/tcp_input.c:2532 tcp_ack+0x1a6f/0x1d60()
    Modules linked in: vfat fat isofs udf usb_storage coretemp rfcomm l2cap
    hci_usb bluetooth xfrm_user xfrm4_tunnel tunnel4 ipcomp esp4 ah4 hfsplus
    binfmt_misc fuse ebtable_broute bridge llc ebtable_nat ebt
    Pid: 0, comm: swapper Tainted: P 2.6.25-rc8-sonne #24
    [] warn_on_slowpath+0x54/0x70
    [] ? ip_output+0x75/0xd0
    [] ? ip_local_out+0x18/0x20
    [] ? ip_queue_xmit+0x1d4/0x3a0
    [] ? __skb_clone+0x22/0xd0
    [] ? tcp_transmit_skb+0x410/0x7b0
    [] tcp_ack+0x1a6f/0x1d60
    [] ? dma_pool_alloc+0xfa/0x1a0
    [] tcp_rcv_established+0x504/0x750
    [] tcp_v4_do_rcv+0xb3/0x1f0
    [] ? __inet_lookup_established+0x17e/0x190
    [] tcp_v4_rcv+0x6bf/0x7c0
    [] ip_local_deliver_finish+0xa9/0x210
    [] ip_local_deliver+0x30/0xa0
    [] ip_rcv_finish+0xff/0x390
    [] ? nf_hook_slow+0xa0/0xf0
    [] ? ip_rcv_finish+0x0/0x390
    [] ip_rcv+0x1e0/0x290
    [] ? ip_rcv_finish+0x0/0x390
    [] ? ip_rcv+0x0/0x290
    [] netif_receive_skb+0x247/0x2d0
    [] sky2_poll+0x4ba/0xc20 [sky2]
    [] ? clocksource_get_next+0x3b/0x50
    [] ? tick_program_event+0x42/0x70
    [] net_rx_action+0xa8/0x130
    [] __do_softirq+0x84/0x100
    [] do_softirq+0x3b/0x50
    [] irq_exit+0x75/0x90
    [] do_IRQ+0x45/0x80
    [] common_interrupt+0x23/0x28
    [] ? acpi_idle_enter_bm+0x28a/0x2f8
    [] cpuidle_idle_call+0x76/0xb0
    [] ? cpuidle_idle_call+0x0/0xb0
    [] cpu_idle+0x6f/0x110
    [] rest_init+0x5d/0x60
    =======================
    ---[ end trace a109db92c4e172c2 ]---
    ------------[ cut here ]------------

    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  2. Re: 2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

    On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:

    > trying to download things, I am seeing this (ignore the tainted, it is
    > from madwifi and although the module is loaded the device was never
    > used)
    >
    > Could anyone make sense of this please?


    ....I'm just trying to find out who and where invariants of the TCP code
    are broken. These were relatively recently enabled (pre-2.6.24 just didn't
    care too much). A number of long standing issues plus bugs from my
    modifications have been fixed because of the more rigid checking :-).

    > ------------[ cut here ]------------
    > WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()


    > ------------[ cut here ]------------
    > WARNING: at net/ipv4/tcp_input.c:1771 tcp_enter_frto+0x267/0x270()


    > ------------[ cut here ]------------
    > WARNING: at net/ipv4/tcp_input.c:2532 tcp_ack+0x1a6f/0x1d60()


    Can you reproduce it?

    Please include netdev next time while report networking related problems.


    --
    i.


    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  3. Re: 2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

    On Thu, 2008-04-03 at 16:26 +0300, Ilpo Järvinen wrote:
    > On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:
    >
    > > trying to download things, I am seeing this (ignore the tainted, it is
    > > from madwifi and although the module is loaded the device was never
    > > used)
    > >
    > > Could anyone make sense of this please?

    >
    > ...I'm just trying to find out who and where invariants of the TCP code
    > are broken. These were relatively recently enabled (pre-2.6.24 just didn't
    > care too much). A number of long standing issues plus bugs from my
    > modifications have been fixed because of the more rigid checking :-).
    >
    > > ------------[ cut here ]------------
    > > WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

    >
    > > ------------[ cut here ]------------
    > > WARNING: at net/ipv4/tcp_input.c:1771 tcp_enter_frto+0x267/0x270()

    >
    > > ------------[ cut here ]------------
    > > WARNING: at net/ipv4/tcp_input.c:2532 tcp_ack+0x1a6f/0x1d60()

    >
    > Can you reproduce it?


    Yes, by massively downloading things :-) But I have no real recipe to
    make it easily reproducible...

    Looks like you are in fact interested in:
    grep WARNING: /var/log/kern.log | cut -c 40- | sort -u

    net/ipv4/tcp_input.c:1771 tcp_enter_frto+0x267/0x270()
    net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()
    net/ipv4/tcp_input.c:2532 tcp_ack+0x1a6f/0x1d60()
    net/ipv4/tcp_input.c:3067 tcp_ack+0x1d2b/0x1d60()

    > Please include netdev next time while report networking related problems.


    OK
    Soeren
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  4. Re: 2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

    On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:

    > On Thu, 2008-04-03 at 16:26 +0300, Ilpo Järvinen wrote:
    > > On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:
    > >
    > > > trying to download things, I am seeing this (ignore the tainted, it is
    > > > from madwifi and although the module is loaded the device was never
    > > > used)
    > > >
    > > > Could anyone make sense of this please?

    > >
    > > ...I'm just trying to find out who and where invariants of the TCP code
    > > are broken. These were relatively recently enabled (pre-2.6.24 just didn't
    > > care too much). A number of long standing issues plus bugs from my
    > > modifications have been fixed because of the more rigid checking :-).
    > >
    > > > ------------[ cut here ]------------
    > > > WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

    > >
    > > > ------------[ cut here ]------------
    > > > WARNING: at net/ipv4/tcp_input.c:1771 tcp_enter_frto+0x267/0x270()

    > >
    > > > ------------[ cut here ]------------
    > > > WARNING: at net/ipv4/tcp_input.c:2532 tcp_ack+0x1a6f/0x1d60()

    > >
    > > Can you reproduce it?

    >
    > Yes, by massively downloading things :-) But I have no real recipe to
    > make it easily reproducible...


    Good :-), no need for recipes, just that you can trigger it more often
    tha once per month or so :-). I probably couldn't trigger it anyway here
    because they're often rather sensitive to network "weather", thus if you
    have problems in reproducing, doing tests around the same phase of the
    date cycle you saw it the first time might help.

    Here's a debug patch which expensively verifies TCP's state in a number
    of places during ACK to find first spot where the actual bug occurs.


    --
    i.


    [PATCH] TCP: debug S+L (for 2.6.25-rcs, incompatible with 2.6.24.y), v1.4

    Debugs sacked & lost skb inconstencies in TCP write queue &
    verifies fackets_out related variables.
    ---
    include/net/tcp.h | 10 +++-
    net/ipv4/tcp_input.c | 29 ++++++++++-
    net/ipv4/tcp_ipv4.c | 134 +++++++++++++++++++++++++++++++++++++++++++++++++
    net/ipv4/tcp_output.c | 24 +++++++--
    4 files changed, 189 insertions(+), 8 deletions(-)

    diff --git a/include/net/tcp.h b/include/net/tcp.h
    index 723b368..5cdc93d 100644
    --- a/include/net/tcp.h
    +++ b/include/net/tcp.h
    @@ -274,6 +274,9 @@ DECLARE_SNMP_STAT(struct tcp_mib, tcp_statistics);
    #define TCP_ADD_STATS_BH(field, val) SNMP_ADD_STATS_BH(tcp_statistics, field, val)
    #define TCP_ADD_STATS_USER(field, val) SNMP_ADD_STATS_USER(tcp_statistics, field, val)

    +extern void tcp_print_queue(struct sock *sk);
    +extern int tcp_verify_wq(struct sock *sk);
    +
    extern void tcp_v4_err(struct sk_buff *skb, u32);

    extern void tcp_shutdown (struct sock *sk, int how);
    @@ -776,7 +779,12 @@ static inline __u32 tcp_current_ssthresh(const struct sock *sk)
    }

    /* Use define here intentionally to get WARN_ON location shown at the caller */
    -#define tcp_verify_left_out(tp) WARN_ON(tcp_left_out(tp) > tp->packets_out)
    +#define tcp_verify_left_out(tp) \
    + do {\
    + int res; \
    + res = tcp_verify_wq((struct sock *)tp); \
    + WARN_ON(res || tcp_left_out(tp) > tp->packets_out); \
    + } while(0)

    extern void tcp_enter_cwr(struct sock *sk, const int set_ssthresh);
    extern __u32 tcp_init_cwnd(struct tcp_sock *tp, struct dst_entry *dst);
    diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
    index 6e46b4c..4dc2c20 100644
    --- a/net/ipv4/tcp_input.c
    +++ b/net/ipv4/tcp_input.c
    @@ -1428,8 +1428,10 @@ tcp_sacktag_write_queue(struct sock *sk, struct sk_buff *ack_skb,
    int first_sack_index;

    if (!tp->sacked_out) {
    - if (WARN_ON(tp->fackets_out))
    + if (WARN_ON(tp->fackets_out)) {
    + tcp_verify_left_out(tp);
    tp->fackets_out = 0;
    + }
    tcp_highest_sack_reset(sk);
    }

    @@ -2140,7 +2142,14 @@ static void tcp_mark_head_lost(struct sock *sk, int packets, int fast_rexmit)
    struct sk_buff *skb;
    int cnt;

    + tcp_verify_left_out(tp);
    +
    BUG_TRAP(packets <= tp->packets_out);
    + if (packets > tp->packets_out) {
    + pr_err("TCP debug %u/%u-%u/%u %d\n",
    + tp->fackets_out, tp->sacked_out, tp->reordering,
    + tp->packets_out, tp->rx_opt.sack_ok);
    + }
    if (tp->lost_skb_hint) {
    skb = tp->lost_skb_hint;
    cnt = tp->lost_cnt_hint;
    @@ -2505,6 +2514,8 @@ static void tcp_fastretrans_alert(struct sock *sk, int pkts_acked, int flag)
    (tcp_fackets_out(tp) > tp->reordering));
    int fast_rexmit = 0;

    + tcp_verify_left_out(tp);
    +
    if (WARN_ON(!tp->packets_out && tp->sacked_out))
    tp->sacked_out = 0;
    if (WARN_ON(!tp->sacked_out && tp->fackets_out))
    @@ -2649,6 +2660,10 @@ static void tcp_fastretrans_alert(struct sock *sk, int pkts_acked, int flag)
    if (do_lost || (tcp_is_fack(tp) && tcp_head_timedout(sk)))
    tcp_update_scoreboard(sk, fast_rexmit);
    tcp_cwnd_down(sk, flag);
    +
    + WARN_ON(tcp_write_queue_head(sk) == NULL);
    + WARN_ON(!tp->packets_out);
    +
    tcp_xmit_retransmit_queue(sk);
    }

    @@ -2801,6 +2816,9 @@ static int tcp_clean_rtx_queue(struct sock *sk, int prior_fackets)
    tcp_mtup_probe_success(sk, skb);
    }

    + WARN_ON((sacked & (TCPCB_SACKED_ACKED|TCPCB_LOST)) ==
    + (TCPCB_SACKED_ACKED|TCPCB_LOST));
    +
    if (sacked & TCPCB_RETRANS) {
    if (sacked & TCPCB_SACKED_RETRANS)
    tp->retrans_out -= acked_pcount;
    @@ -2891,6 +2909,8 @@ static int tcp_clean_rtx_queue(struct sock *sk, int prior_fackets)
    }
    }

    + tcp_verify_left_out(tp);
    +
    #if FASTRETRANS_DEBUG > 0
    BUG_TRAP((int)tp->sacked_out >= 0);
    BUG_TRAP((int)tp->lost_out >= 0);
    @@ -3179,6 +3199,8 @@ static int tcp_ack(struct sock *sk, struct sk_buff *skb, int flag)
    prior_fackets = tp->fackets_out;
    prior_in_flight = tcp_packets_in_flight(tp);

    + tcp_verify_left_out(tp);
    +
    if (!(flag & FLAG_SLOWPATH) && after(ack, prior_snd_una)) {
    /* Window is constant, pure forward advance.
    * No more checks are required.
    @@ -3238,9 +3260,14 @@ static int tcp_ack(struct sock *sk, struct sk_buff *skb, int flag)
    tcp_cong_avoid(sk, ack, prior_in_flight);
    }

    + if (WARN_ON((icsk->icsk_ca_state == TCP_CA_Open) && tcp_left_out(tp)))
    + tcp_print_queue(sk);
    +
    if ((flag & FLAG_FORWARD_PROGRESS) || !(flag & FLAG_NOT_DUP))
    dst_confirm(sk->sk_dst_cache);

    + tcp_verify_left_out(tp);
    +
    return 1;

    no_queue:
    diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
    index ef141b8..356ee6e 100644
    --- a/net/ipv4/tcp_ipv4.c
    +++ b/net/ipv4/tcp_ipv4.c
    @@ -108,6 +108,140 @@ struct inet_hashinfo __cacheline_aligned tcp_hashinfo = {
    .lhash_wait = __WAIT_QUEUE_HEAD_INITIALIZER(tcp_hashinfo.lhash_w ait),
    };

    +void tcp_print_queue(struct sock *sk)
    +{
    + struct tcp_sock *tp = tcp_sk(sk);
    + struct sk_buff *skb;
    + char s[50+1];
    + char h[50+1];
    + int idx = 0;
    + int i;
    +
    + i = 0;
    + tcp_for_write_queue(skb, sk) {
    + if (skb == tcp_send_head(sk))
    + printk(KERN_ERR "head %u %p\n", i, skb);
    + else
    + printk(KERN_ERR "skb %u %p\n", i, skb);
    + i++;
    + }
    +
    + tcp_for_write_queue(skb, sk) {
    + if (skb == tcp_send_head(sk))
    + break;
    +
    + for (i = 0; i < tcp_skb_pcount(skb); i++) {
    + if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED) {
    + s[idx] = 'S';
    + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST)
    + s[idx] = 'B';
    +
    + } else if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) {
    + s[idx] = 'L';
    + } else {
    + s[idx] = ' ';
    + }
    + if (s[idx] != ' ' && skb->len < tp->mss_cache)
    + s[idx] += 'a' - 'A';
    +
    + if (i == 0) {
    + if (skb == tcp_highest_sack(sk))
    + h[idx] = 'h';
    + else
    + h[idx] = '+';
    + } else {
    + h[idx] = '-';
    + }
    +
    + if (++idx >= 50) {
    + s[idx] = 0;
    + h[idx] = 0;
    + printk(KERN_ERR "TCP wq(s) %s\n", s);
    + printk(KERN_ERR "TCP wq(h) %s\n", h);
    + idx = 0;
    + }
    + }
    + }
    + if (idx) {
    + s[idx] = '<';
    + s[idx+1] = 0;
    + h[idx] = '<';
    + h[idx+1] = 0;
    + printk(KERN_ERR "TCP wq(s) %s\n", s);
    + printk(KERN_ERR "TCP wq(h) %s\n", h);
    + }
    + printk(KERN_ERR "l%u s%u f%u p%u seq: su%u hs%u sn%u\n",
    + tp->lost_out, tp->sacked_out, tp->fackets_out, tp->packets_out,
    + tp->snd_una, tcp_highest_sack_seq(tp), tp->snd_nxt);
    +}
    +
    +int tcp_verify_wq(struct sock *sk)
    +{
    + struct tcp_sock *tp = tcp_sk(sk);
    + u32 lost = 0;
    + u32 sacked = 0;
    + u32 packets = 0;
    + u32 fackets = 0;
    + int hs_valid = 0;
    + int inconsistent = 0;
    + struct sk_buff *skb;
    +
    + tcp_for_write_queue(skb, sk) {
    + if (skb == tcp_send_head(sk))
    + break;
    +
    + if ((fackets == packets) && (skb == tp->highest_sack))
    + hs_valid = 1;
    +
    + packets += tcp_skb_pcount(skb);
    +
    + if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED) {
    + sacked += tcp_skb_pcount(skb);
    + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST)
    + printk(KERN_ERR "Sacked bitmap S+L: %u %u-%u/%u\n",
    + TCP_SKB_CB(skb)->sacked,
    + TCP_SKB_CB(skb)->end_seq - tp->snd_una,
    + TCP_SKB_CB(skb)->seq - tp->snd_una,
    + tp->snd_una);
    + fackets = packets;
    + hs_valid = 0;
    + }
    + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST)
    + lost += tcp_skb_pcount(skb);
    + }
    +
    + if ((fackets == packets) && (tp->highest_sack == tcp_send_head(sk)))
    + hs_valid = 1;
    +
    + if ((lost != tp->lost_out) ||
    + (tcp_is_sack(tp) && (sacked != tp->sacked_out)) ||
    + ((sacked || (tcp_is_sack(tp) && tp->sacked_out)) && !hs_valid) ||
    + (packets != tp->packets_out) ||
    + (fackets != tp->fackets_out) ||
    + (tcp_is_reno(tp) && tp->packets_out &&
    + (tcp_left_out(tp) == tp->packets_out) &&
    + !(TCP_SKB_CB(tcp_write_queue_head(sk))->sacked & TCPCB_LOST)) ||
    + tcp_left_out(tp) > tp->packets_out) {
    + printk(KERN_ERR "P: %u L: %u vs %u S: %u vs %u F: %u vs %u w: %u-%u (%u)\n",
    + tp->packets_out,
    + lost, tp->lost_out,
    + sacked, tp->sacked_out,
    + fackets, tp->fackets_out,
    + tp->snd_una, tp->snd_nxt,
    + tp->rx_opt.sack_ok);
    + tcp_print_queue(sk);
    + inconsistent = 1;
    + }
    +
    + WARN_ON(lost != tp->lost_out);
    + WARN_ON(tcp_is_sack(tp) && (sacked != tp->sacked_out));
    + WARN_ON(packets != tp->packets_out);
    + WARN_ON(fackets != tp->fackets_out);
    + WARN_ON(tcp_left_out(tp) > tp->packets_out);
    +
    + return inconsistent;
    +}
    +
    static inline __u32 tcp_v4_init_sequence(struct sk_buff *skb)
    {
    return secure_tcp_sequence_number(ip_hdr(skb)->daddr,
    diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c
    index 6e25540..e7d78c2 100644
    --- a/net/ipv4/tcp_output.c
    +++ b/net/ipv4/tcp_output.c
    @@ -779,10 +779,9 @@ int tcp_fragment(struct sock *sk, struct sk_buff *skb, u32 len,
    tp->lost_out -= diff;

    /* Adjust Reno SACK estimate. */
    - if (tcp_is_reno(tp) && diff > 0) {
    + if (tcp_is_reno(tp) && diff > 0)
    tcp_dec_pcount_approx_int(&tp->sacked_out, diff);
    - tcp_verify_left_out(tp);
    - }
    +
    tcp_adjust_fackets_out(sk, skb, diff);
    }

    @@ -790,6 +789,8 @@ int tcp_fragment(struct sock *sk, struct sk_buff *skb, u32 len,
    skb_header_release(buff);
    tcp_insert_write_queue_after(skb, buff, sk);

    + tcp_verify_left_out(tp);
    +
    return 0;
    }

    @@ -1471,6 +1472,7 @@ static int tcp_write_xmit(struct sock *sk, unsigned int mss_now, int nonagle)
    } else if (result > 0) {
    sent_pkts = 1;
    }
    + tcp_verify_left_out(tp);

    while ((skb = tcp_send_head(sk))) {
    unsigned int limit;
    @@ -1772,6 +1774,7 @@ static void tcp_retrans_try_collapse(struct sock *sk, struct sk_buff *skb,
    tcp_clear_retrans_hints_partial(tp);

    sk_wmem_free_skb(sk, next_skb);
    + tcp_verify_left_out(tp);
    }

    /* Do a simple retransmit without using the backoff mechanisms in
    @@ -1803,13 +1806,13 @@ void tcp_simple_retransmit(struct sock *sk)
    }
    }

    + tcp_verify_left_out(tp);
    +
    tcp_clear_all_retrans_hints(tp);

    if (!lost)
    return;

    - tcp_verify_left_out(tp);
    -
    /* Don't muck with the congestion window here.
    * Reason is that we do not increase amount of _data_
    * in network, but units changed and effective
    @@ -1892,10 +1895,13 @@ int tcp_retransmit_skb(struct sock *sk, struct sk_buff *skb)
    (TCP_SKB_CB(skb)->flags & TCPCB_FLAG_FIN) &&
    tp->snd_una == (TCP_SKB_CB(skb)->end_seq - 1)) {
    if (!pskb_trim(skb, 0)) {
    + WARN_ON(TCP_SKB_CB(skb)->sacked & TCPCB_LOST);
    /* Reuse, even though it does some unnecessary work */
    tcp_init_nondata_skb(skb, TCP_SKB_CB(skb)->end_seq - 1,
    TCP_SKB_CB(skb)->flags);
    skb->ip_summed = CHECKSUM_NONE;
    +
    + tcp_verify_left_out(tp);
    }
    }

    @@ -1978,8 +1984,10 @@ void tcp_xmit_retransmit_queue(struct sock *sk)
    * packet to be MSS sized and all the
    * packet counting works out.
    */
    - if (tcp_packets_in_flight(tp) >= tp->snd_cwnd)
    + if (tcp_packets_in_flight(tp) >= tp->snd_cwnd) {
    + tcp_verify_left_out(tp);
    return;
    + }

    if (sacked & TCPCB_LOST) {
    if (!(sacked & (TCPCB_SACKED_ACKED|TCPCB_SACKED_RETRANS))) {
    @@ -2005,6 +2013,8 @@ void tcp_xmit_retransmit_queue(struct sock *sk)
    }
    }

    + tcp_verify_left_out(tp);
    +
    /* OK, demanded retransmission is finished. */

    /* Forward retransmissions are possible only during Recovery. */
    @@ -2062,6 +2072,8 @@ void tcp_xmit_retransmit_queue(struct sock *sk)

    NET_INC_STATS_BH(LINUX_MIB_TCPFORWARDRETRANS);
    }
    +
    + tcp_verify_left_out(tp);
    }

    /* Send a fin. The caller locks the socket for us. This cannot be
    --
    1.5.2.2

  5. Re: 2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

    On Fri, 2008-04-04 at 21:51 +0300, Ilpo Järvinen wrote:
    > On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:
    >
    > > On Thu, 2008-04-03 at 16:26 +0300, Ilpo Järvinen wrote:
    > > > On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:
    > > >
    > > > > trying to download things, I am seeing this (ignore the tainted, it is
    > > > > from madwifi and although the module is loaded the device was never
    > > > > used)
    > > > >
    > > > > Could anyone make sense of this please?
    > > >
    > > > ...I'm just trying to find out who and where invariants of the TCP code
    > > > are broken. These were relatively recently enabled (pre-2.6.24 just didn't
    > > > care too much). A number of long standing issues plus bugs from my
    > > > modifications have been fixed because of the more rigid checking :-).
    > > >
    > > > > ------------[ cut here ]------------
    > > > > WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()
    > > >
    > > > > ------------[ cut here ]------------
    > > > > WARNING: at net/ipv4/tcp_input.c:1771 tcp_enter_frto+0x267/0x270()
    > > >
    > > > > ------------[ cut here ]------------
    > > > > WARNING: at net/ipv4/tcp_input.c:2532 tcp_ack+0x1a6f/0x1d60()
    > > >
    > > > Can you reproduce it?

    > >
    > > Yes, by massively downloading things :-) But I have no real recipe to
    > > make it easily reproducible...

    >
    > Good :-), no need for recipes, just that you can trigger it more often
    > tha once per month or so :-). I probably couldn't trigger it anyway here
    > because they're often rather sensitive to network "weather", thus if you
    > have problems in reproducing, doing tests around the same phase of the
    > date cycle you saw it the first time might help.
    >
    > Here's a debug patch which expensively verifies TCP's state in a number
    > of places during ACK to find first spot where the actual bug occurs.


    OK I am getting this now as the first spot:

    P: 4 L: 2 vs 2 S: 0 vs 3 F: 0 vs 0 w: 4023500226-4023505874 (0)
    skb 0 f495c180
    skb 1 f480a180
    skb 2 f4994600
    head 3 f495c780
    skb 4 f5b32480
    TCP wq(s) LL <
    WARNING: at net/ipv4/tcp_ipv4.c:240 tcp_verify_wq+0x319/0x3c0()

    another one:
    WARNING: at net/ipv4/tcp_output.c:1475 __tcp_push_pending_frames+0x70/0x830()


    P: 4 L: 2 vs 2 S: 0 vs 3 F: 0 vs 0 w: 4023500226-4023505874 (0)
    skb 0 f495c180
    skb 1 f480a180
    skb 2 f4994600
    head 3 f495c780
    skb 4 f5b32480
    TCP wq(s) LL <
    TCP wq(h) +-++<
    l2 s3 f0 p4 seq: su4023500226 hs241530103 sn4023505874
    ------------[ cut here ]------------
    WARNING: at net/ipv4/tcp_ipv4.c:240 tcp_verify_wq+0x319/0x3c0()

    Soeren
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  6. Re: 2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

    On Sat, 5 Apr 2008, Soeren Sonnenburg wrote:

    > On Fri, 2008-04-04 at 21:51 +0300, Ilpo Järvinen wrote:
    > > On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:
    > >
    > > > On Thu, 2008-04-03 at 16:26 +0300, Ilpo Järvinen wrote:
    > > > > On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:
    > > > >
    > > > > > trying to download things, I am seeing this (ignore the tainted, it is
    > > > > > from madwifi and although the module is loaded the device was never
    > > > > > used)
    > > > > >
    > > > > > Could anyone make sense of this please?
    > > > >
    > > > > ...I'm just trying to find out who and where invariants of the TCP code
    > > > > are broken. These were relatively recently enabled (pre-2.6.24 just didn't
    > > > > care too much). A number of long standing issues plus bugs from my
    > > > > modifications have been fixed because of the more rigid checking :-).
    > > > >
    > > > > > ------------[ cut here ]------------
    > > > > > WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()
    > > > >
    > > > > > ------------[ cut here ]------------
    > > > > > WARNING: at net/ipv4/tcp_input.c:1771 tcp_enter_frto+0x267/0x270()
    > > > >
    > > > > > ------------[ cut here ]------------
    > > > > > WARNING: at net/ipv4/tcp_input.c:2532 tcp_ack+0x1a6f/0x1d60()
    > > > >
    > > > > Can you reproduce it?
    > > >
    > > > Yes, by massively downloading things :-) But I have no real recipe to
    > > > make it easily reproducible...

    > >
    > > Good :-), no need for recipes, just that you can trigger it more often
    > > tha once per month or so :-). I probably couldn't trigger it anyway here
    > > because they're often rather sensitive to network "weather", thus if you
    > > have problems in reproducing, doing tests around the same phase of the
    > > date cycle you saw it the first time might help.
    > >
    > > Here's a debug patch which expensively verifies TCP's state in a number
    > > of places during ACK to find first spot where the actual bug occurs.

    >
    > OK I am getting this now as the first spot:
    >
    > P: 4 L: 2 vs 2 S: 0 vs 3 F: 0 vs 0 w: 4023500226-4023505874 (0)
    > skb 0 f495c180
    > skb 1 f480a180
    > skb 2 f4994600
    > head 3 f495c780
    > skb 4 f5b32480
    > TCP wq(s) LL <
    > WARNING: at net/ipv4/tcp_ipv4.c:240 tcp_verify_wq+0x319/0x3c0()
    >
    > another one:
    > WARNING: at net/ipv4/tcp_output.c:1475 __tcp_push_pending_frames+0x70/0x830()
    >
    >
    > P: 4 L: 2 vs 2 S: 0 vs 3 F: 0 vs 0 w: 4023500226-4023505874 (0)
    > skb 0 f495c180
    > skb 1 f480a180
    > skb 2 f4994600
    > head 3 f495c780
    > skb 4 f5b32480
    > TCP wq(s) LL <
    > TCP wq(h) +-++<
    > l2 s3 f0 p4 seq: su4023500226 hs241530103 sn4023505874
    > ------------[ cut here ]------------
    > WARNING: at net/ipv4/tcp_ipv4.c:240 tcp_verify_wq+0x319/0x3c0()


    Please don't cut the log! It is caught here because 2+3 > 4 :-) but I need
    the full log with stacktraces this time to figure it out.

    --
    i.

  7. Re: 2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

    On Sat, 2008-04-05 at 20:52 +0300, Ilpo Järvinen wrote:
    > On Sat, 5 Apr 2008, Soeren Sonnenburg wrote:
    >
    > > On Fri, 2008-04-04 at 21:51 +0300, Ilpo Järvinen wrote:
    > > > On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:
    > > >
    > > > > On Thu, 2008-04-03 at 16:26 +0300, Ilpo Järvinen wrote:
    > > > > > On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:
    > > > > >
    > > > > > > trying to download things, I am seeing this (ignore the tainted, it is
    > > > > > > from madwifi and although the module is loaded the device was never
    > > > > > > used)
    > > > > > >
    > > > > > > Could anyone make sense of this please?

    [...]
    > > >
    > > > Here's a debug patch which expensively verifies TCP's state in a number
    > > > of places during ACK to find first spot where the actual bug occurs.

    > >
    > > OK I am getting this now as the first spot:
    > >
    > > P: 4 L: 2 vs 2 S: 0 vs 3 F: 0 vs 0 w: 4023500226-4023505874 (0)
    > > skb 0 f495c180
    > > skb 1 f480a180
    > > skb 2 f4994600
    > > head 3 f495c780
    > > skb 4 f5b32480
    > > TCP wq(s) LL <
    > > WARNING: at net/ipv4/tcp_ipv4.c:240 tcp_verify_wq+0x319/0x3c0()
    > >
    > > another one:
    > > WARNING: at net/ipv4/tcp_output.c:1475 __tcp_push_pending_frames+0x70/0x830()
    > >
    > >
    > > P: 4 L: 2 vs 2 S: 0 vs 3 F: 0 vs 0 w: 4023500226-4023505874 (0)
    > > skb 0 f495c180
    > > skb 1 f480a180
    > > skb 2 f4994600
    > > head 3 f495c780
    > > skb 4 f5b32480
    > > TCP wq(s) LL <
    > > TCP wq(h) +-++<
    > > l2 s3 f0 p4 seq: su4023500226 hs241530103 sn4023505874
    > > ------------[ cut here ]------------
    > > WARNING: at net/ipv4/tcp_ipv4.c:240 tcp_verify_wq+0x319/0x3c0()

    >
    > Please don't cut the log! It is caught here because 2+3 > 4 :-) but I need
    > the full log with stacktraces this time to figure it out.


    Look here
    http://nn7.de/debugging/tcp.log :-)

    HTH,
    Soeren

    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  8. Re: 2.6.25-rc8: WARNING: at net/ipv4/tcp_input.c:2173 tcp_mark_head_lost+0x11d/0x150()

    On Sat, 5 Apr 2008, Soeren Sonnenburg wrote:

    > On Sat, 2008-04-05 at 20:52 +0300, Ilpo Järvinen wrote:
    > > On Sat, 5 Apr 2008, Soeren Sonnenburg wrote:
    > >
    > > > On Fri, 2008-04-04 at 21:51 +0300, Ilpo Järvinen wrote:
    > > > > On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:
    > > > >
    > > > > > On Thu, 2008-04-03 at 16:26 +0300, Ilpo Järvinen wrote:
    > > > > > > On Thu, 3 Apr 2008, Soeren Sonnenburg wrote:
    > > > > > >
    > > > > > > > trying to download things, I am seeing this (ignore the tainted, it is
    > > > > > > > from madwifi and although the module is loaded the device was never
    > > > > > > > used)
    > > > > > > >
    > > > > > > > Could anyone make sense of this please?

    > [...]
    > > > >
    > > > > Here's a debug patch which expensively verifies TCP's state in a number
    > > > > of places during ACK to find first spot where the actual bug occurs.
    > > >
    > > > OK I am getting this now as the first spot:
    > > >
    > > > P: 4 L: 2 vs 2 S: 0 vs 3 F: 0 vs 0 w: 4023500226-4023505874 (0)
    > > > skb 0 f495c180
    > > > skb 1 f480a180
    > > > skb 2 f4994600
    > > > head 3 f495c780
    > > > skb 4 f5b32480
    > > > TCP wq(s) LL <
    > > > WARNING: at net/ipv4/tcp_ipv4.c:240 tcp_verify_wq+0x319/0x3c0()
    > > >
    > > > another one:
    > > > WARNING: at net/ipv4/tcp_output.c:1475 __tcp_push_pending_frames+0x70/0x830()
    > > >
    > > >
    > > > P: 4 L: 2 vs 2 S: 0 vs 3 F: 0 vs 0 w: 4023500226-4023505874 (0)
    > > > skb 0 f495c180
    > > > skb 1 f480a180
    > > > skb 2 f4994600
    > > > head 3 f495c780
    > > > skb 4 f5b32480
    > > > TCP wq(s) LL <
    > > > TCP wq(h) +-++<
    > > > l2 s3 f0 p4 seq: su4023500226 hs241530103 sn4023505874
    > > > ------------[ cut here ]------------
    > > > WARNING: at net/ipv4/tcp_ipv4.c:240 tcp_verify_wq+0x319/0x3c0()

    > >
    > > Please don't cut the log! It is caught here because 2+3 > 4 :-) but I need
    > > the full log with stacktraces this time to figure it out.

    >
    > Look here
    > http://nn7.de/debugging/tcp.log :-)


    Thanks. I had already figured it out while waiting :-), it's GSO+NewReno
    bad interaction, I'll fix it on Monday (unless somebody is faster than
    me)... And once again, this ain't a regression. Thanks for helping out
    enourmously.

    --
    i.

+ Reply to Thread