netdev - Re: WARN_ON in TLP causing RT throttling

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <f4103fc7d67dff06718bbc5a992170cb@codeaurora.org>
Date:   Thu, 27 Sep 2018 18:16:24 -0600
From:   stranche@...eaurora.org
To:     Yuchung Cheng <ycheng@...gle.com>
Cc:     Eric Dumazet <eric.dumazet@...il.com>, soheil@...gle.com,
        netdev@...r.kernel.org
Subject: Re: WARN_ON in TLP causing RT throttling

On 2018-09-27 13:14, Yuchung Cheng wrote:
> On Wed, Sep 26, 2018 at 5:09 PM, Eric Dumazet <eric.dumazet@...il.com> 
> wrote:
>> 
>> 
>> 
>> On 09/26/2018 04:46 PM, stranche@...eaurora.org wrote:
>> > Hi Eric,
>> >
>> > Someone recently reported a crash to us on the 4.14.62 kernel where excessive
>> > WARNING prints were spamming the logs and causing watchdog bites. The kernel
>> > does have the following commit by Soheil:
>> > bffd168c3fc5 "tcp: clear tp->packets_out when purging write queue"
>> >
>> > Before this bug we see over 1 second of continuous WARN_ON prints from
>> > tcp_send_loss_probe() like so:
>> >
>> > 7795.530450:   <2>  tcp_send_loss_probe+0x194/0x1b8
>> > 7795.534833:   <2>  tcp_write_timer_handler+0xf8/0x1c4
>> > 7795.539492:   <2>  tcp_write_timer+0x4c/0x74
>> > 7795.543348:   <2>  call_timer_fn+0xc0/0x1b4
>> > 7795.547113:   <2>  run_timer_softirq+0x248/0x81c
>> >
>> > Specifically, the prints come from the following check:
>> >
>> >     /* Retransmit last segment. */
>> >     if (WARN_ON(!skb))
>> >         goto rearm_timer;
>> >
>> > Since skb is always NULL, we know there's nothing on the write queue or the
>> > retransmit queue, so we just keep resetting the timer, waiting for more data
>> > to be queued. However, we were able to determine that the TCP socket is in the
>> > TCP_FIN_WAIT1 state, so we will no longer be sending any data and these queues
>> > remain empty.
>> >
>> > Would it be appropriate to stop resetting the TLP timer if we detect that the
>> > connection is starting to close and we have no more data to send the probe with,
>> > or is there some way that this scenario should already be handled?
>> >
>> > Unfortunately, we don't have a reproducer for this crash.
>> >
>> 
>> Something is fishy.
>> 
>> If there is no skb in the queues, then tp->packets_out should be 0,
>> therefore tcp_rearm_rto() should simply call 
>> inet_csk_clear_xmit_timer(sk, ICSK_TIME_RETRANS);
>> 
>> I have never seen this report before.
> Do you use Fast Open? I am wondering if its a bug when a TFO server
> closes the socket before the handshake finishes...
> 
> Either way, it's pretty safe to just stop TLP if write queue is empty
> for any unexpected reason.
> 
>> 
Hi Yuchung,

Based on the dumps we were able to get, it appears that TFO was not used 
in this case.
We also tried some local experiments where we dropped incoming SYN 
packets after already
successful TFO connections on the receive side to see if TFO would 
trigger this scenario, but
have not been able to reproduce it.

One other interesting thing we found is that the socket never sent or 
received any data. It only
sent/received the packets for the initial handshake and the outgoing 
FIN.