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] [day] [month] [year] [list]

Date:   Tue, 2 Oct 2018 14:19:28 -0700
From:   Yuchung Cheng <ycheng@...gle.com>
To:     stranche@...eaurora.org
Cc:     Eric Dumazet <eric.dumazet@...il.com>,
        Soheil Hassas Yeganeh <soheil@...gle.com>,
        netdev <netdev@...r.kernel.org>
Subject: Re: WARN_ON in TLP causing RT throttling

On Thu, Sep 27, 2018 at 5:16 PM, <stranche@...eaurora.org> wrote:
>
> 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.
I wonder if there's a bug in tcp_rtx_queue. rtx_queue should have at
least the FIN packet pending to be acked in TCP_FIN_WAIT1. And the
warning should only show up once if packets_out is 0 due to the check
in tcp_rearm_rto. so it seems packets_out is non-zero (i.e. counting a
FIN) but tcp_rtx_queue has become empty. hmmm