Message-ID: <c84d0877-43a1-9a52-0046-e26b614a5aa6@candelatech.com>
Date:   Tue, 11 Jan 2022 13:35:23 -0800
From:   Ben Greear <greearb@...delatech.com>
To:     Eric Dumazet <eric.dumazet@...il.com>,
        Neal Cardwell <ncardwell@...gle.com>, edumazet@...gle.com
Cc:     netdev <netdev@...r.kernel.org>
Subject: Re: Debugging stuck tcp connection across localhost

On 1/11/22 2:46 AM, Eric Dumazet wrote:
> 
> On 1/10/22 10:10, Ben Greear wrote:
>> On 1/6/22 2:26 PM, Ben Greear wrote:
>>> On 1/6/22 12:04 PM, Neal Cardwell wrote:
>>>> On Thu, Jan 6, 2022 at 2:05 PM Ben Greear <greearb@...delatech.com> wrote:
>>>>>
>>>>> On 1/6/22 8:16 AM, Neal Cardwell wrote:
>>>>>> On Thu, Jan 6, 2022 at 10:39 AM Ben Greear <greearb@...delatech.com> wrote:
>>>>>>>
>>>>>>> On 1/6/22 7:20 AM, Neal Cardwell wrote:
>>>>>>>> On Thu, Jan 6, 2022 at 10:06 AM Ben Greear <greearb@...delatech.com> wrote:
>>>>>>>>>
>>>>>>>>> Hello,
>>>>>>>>>
>>>>>>>>> I'm working on a strange problem, and could use some help if anyone has ideas.
>>>>>>>>>
>>>>>>>>> On a heavily loaded system (500+ wifi station devices, VRF device per 'real' netdev,
>>>>>>>>> traffic generation on the netdevs, etc), I see cases where two processes trying
>>>>>>>>> to communicate across localhost with TCP seem to get a stuck network
>>>>>>>>> connection:
>>>>>>>>>
>>>>>>>>> [greearb@...dt7 ben_debug]$ grep 4004 netstat.txt |grep 127.0.0.1
>>>>>>>>> tcp        0 7988926 127.0.0.1:4004 127.0.0.1:23184 ESTABLISHED
>>>>>>>>> tcp        0  59805 127.0.0.1:23184 127.0.0.1:4004 ESTABLISHED
>>>>>>>>>
>>>>>>>>> Both processes in question continue to execute, and as far as I can tell, they are properly
>>>>>>>>> attempting to read/write the socket, but they are reading/writing 0 bytes (these sockets
>>>>>>>>> are non blocking).  If one was stuck not reading, I would expect netstat
>>>>>>>>> to show bytes in the rcv buffer, but it is zero as you can see above.
>>>>>>>>>
>>>>>>>>> Kernel is 5.15.7+ local hacks.  I can only reproduce this in a big messy complicated
>>>>>>>>> test case, with my local ath10k-ct and other patches that enable virtual wifi stations,
>>>>>>>>> but my code can grab logs at time it sees the problem.  Is there anything
>>>>>>>>> more I can do to figure out why the TCP connection appears to be stuck?
>>>>>>>>
>>>>>>>> It could be very useful to get more information about the state of all
>>>>>>>> the stuck connections (sender and receiver side) with something like:
>>>>>>>>
>>>>>>>>      ss -tinmo 'sport = :4004 or sport = :4004'
>>>>>>>>
>>>>>>>> I would recommend downloading and building a recent version of the
>>>>>>>> 'ss' tool to maximize the information. Here is a recipe for doing
>>>>>>>> that:
>>>>>>>>
>>>>>>>> https://github.com/google/bbr/blob/master/Documentation/bbr-faq.md#how-can-i-monitor-linux-tcp-bbr-connections
>>>>>
>>>>> Hello Neal,
>>>>>
>>>>> Here is the ss output from when the problem was happening. I think you can ignore the non-127.0.0.1
>>>>> connections, but I left them in just in case it is somehow helpful.
>>>>>
>>>>> In addition, the pcap capture file is uploaded here:
>>>>>
>>>>> http://www.candelatech.com/downloads/trace-lo-4004.pcap
>>>>>
>>>>> The problem was happening in this time frame:
>>>>>
>>>>> [root@...23c-0bdd ~]# date
>>>>> Thu 06 Jan 2022 10:14:49 AM PST
>>>>> [root@...23c-0bdd ~]# ss -tinmo 'dport = :4004 or sport = :4004'
>>>>> State       Recv-Q       Send-Q               Local Address:Port                Peer Address:Port
>>>>>
>>>>> ESTAB       0            222024 127.0.0.1:57224 127.0.0.1:4004 timer:(persist,1min23sec,9)
>>>>> skmem:(r0,rb2000000,t0,tb2000000,f2232,w227144,o0,bl0,d0) ts sack reno wscale:10,4 rto:201 backoff:9 rtt:0.866/0.944 ato:40 mss:65483 pmtu:65535 rcvmss:65483
>>>>> advmss:65483 cwnd:10 bytes_sent:36810035 bytes_retrans:22025 bytes_acked:31729223 bytes_received:228063971 segs_out:20134 segs_in:17497 data_segs_out:11969
>>>>> data_segs_in:16642 send 6049237875bps lastsnd:3266 lastrcv:125252 lastack:125263 pacing_rate 12093239064bps delivery_rate 130966000000bps delivered:11863
>>>>> app_limited busy:275880ms rwnd_limited:21ms(0.0%) retrans:0/2 dsack_dups:2 rcv_rtt:0.671 rcv_space:1793073 rcv_ssthresh:934517 notsent:222024 minrtt:0.013
>>>>> ESTAB       0            0 192.168.200.34:4004 192.168.200.34:16906
>>>>>           skmem:(r0,rb19521831,t0,tb2626560,f0,w0,o0,bl0,d0) ts sack reno wscale:10,10 rto:201 rtt:0.483/0.64 ato:40 mss:22016 pmtu:65535 rcvmss:65483 
>>>>> advmss:65483
>>>>> cwnd:5 ssthresh:5 bytes_sent:8175956 bytes_retrans:460 bytes_acked:8174668 bytes_received:20820708 segs_out:3635 segs_in:2491 data_segs_out:2377
>>>>> data_segs_in:2330 send 1823271222bps lastsnd:125253 lastrcv:125250 lastack:125251 pacing_rate 2185097952bps delivery_rate 70451200000bps delivered:2372
>>>>> busy:14988ms rwnd_limited:1ms(0.0%) retrans:0/5 rcv_rtt:1.216 rcv_space:779351 rcv_ssthresh:9759798 minrtt:0.003
>>>>> ESTAB       0            139656 192.168.200.34:16908 192.168.200.34:4004 timer:(persist,1min52sec,2)
>>>>> skmem:(r0,rb2000000,t0,tb2000000,f3960,w143496,o0,bl0,d0) ts sack reno wscale:10,10 rto:37397 backoff:2 rtt:4182.62/8303.35 ato:40 mss:65483 pmtu:65535
>>>>> rcvmss:22016 advmss:65483 cwnd:10 bytes_sent:22351275 bytes_retrans:397320 bytes_acked:20703982 bytes_received:7815946 segs_out:2585 segs_in:3642
>>>>> data_segs_out:2437 data_segs_in:2355 send 1252479bps lastsnd:7465 lastrcv:125250 lastack:125253 pacing_rate 2504952bps delivery_rate 15992bps delivered:2357
>>>>> busy:271236ms retrans:0/19 rcv_rtt:0.004 rcv_space:288293 rcv_ssthresh:43690 notsent:139656 minrtt:0.004
>>>>> ESTAB       0            460 192.168.200.34:4004 192.168.200.34:16908 timer:(on,1min23sec,9)
>>>>> skmem:(r0,rb9433368,t0,tb2626560,f2356,w1740,o0,bl0,d0) ts sack reno wscale:10,10 rto:102912 backoff:9 rtt:0.741/1.167 ato:40 mss:22016 pmtu:65535
>>>>> rcvmss:65483 advmss:65483 cwnd:1 ssthresh:2 bytes_sent:7850211 bytes_retrans:33437 bytes_acked:7815486 bytes_received:20703981 segs_out:3672 segs_in:2504
>>>>> data_segs_out:2380 data_segs_in:2356 send 237689609bps lastsnd:19753 lastrcv:158000 lastack:125250 pacing_rate 854817384bps delivery_rate 115645432bps
>>>>> delivered:2355 busy:200993ms unacked:1 retrans:0/24 lost:1 rcv_rtt:1.439 rcv_space:385874 rcv_ssthresh:4715943 minrtt:0.003
>>>>> ESTAB       0            147205 192.168.200.34:16906 192.168.200.34:4004 timer:(persist,1min46sec,9)
>>>>> skmem:(r0,rb2000000,t0,tb2000000,f507,w151045,o0,bl0,d0) ts sack reno wscale:10,10 rto:223 backoff:9 rtt:11.4/18.962 ato:40 mss:65483 pmtu:65535 rcvmss:22016
>>>>> advmss:65483 cwnd:10 bytes_sent:23635760 bytes_retrans:220124 bytes_acked:20820709 bytes_received:8174668 segs_out:2570 segs_in:3625 data_segs_out:2409
>>>>> data_segs_in:2371 send 459529825bps lastsnd:7465 lastrcv:125253 lastack:125250 pacing_rate 918999184bps delivery_rate 43655333328bps delivered:2331 
>>>>> app_limited
>>>>> busy:185315ms retrans:0/14 rcv_rtt:0.005 rcv_space:220160 rcv_ssthresh:43690 notsent:147205 minrtt:0.003
>>>>> ESTAB       0            3928980 127.0.0.1:4004 127.0.0.1:57224 timer:(persist,7.639ms,8)
>>>>> skmem:(r0,rb50000000,t0,tb3939840,f108,w4005780,o0,bl0,d3) ts sack reno wscale:4,10 rto:251 backoff:8 rtt:13.281/25.84 ato:40 mss:65483 pmtu:65535
>>>>> rcvmss:65483 advmss:65483 cwnd:10 ssthresh:10 bytes_sent:312422779 bytes_retrans:245567 bytes_acked:228063971 bytes_received:31729222 segs_out:18944
>>>>> segs_in:20021 data_segs_out:18090 data_segs_in:11862 send 394446201bps lastsnd:56617 lastrcv:125271 lastack:125252 pacing_rate 709983112bps delivery_rate
>>>>> 104772800000bps delivered:16643 app_limited busy:370468ms rwnd_limited:127ms(0.0%) retrans:0/26 rcv_rtt:7666.22 rcv_space:2279928 rcv_ssthresh:24999268
>>>>> notsent:3928980 minrtt:0.003
>>>>> [root@...23c-0bdd ~]# date
>>>>> Thu 06 Jan 2022 10:14:57 AM PST
>>>>> [root@...23c-0bdd ~]# ss -tinmo 'dport = :4004 or sport = :4004'
>>>>> State       Recv-Q       Send-Q               Local Address:Port                Peer Address:Port
>>>>>
>>>>> ESTAB       0            222208 127.0.0.1:57224 127.0.0.1:4004 timer:(persist,1min11sec,9)
>>>>> skmem:(r0,rb2000000,t0,tb2000000,f2048,w227328,o0,bl0,d0) ts sack reno wscale:10,4 rto:201 backoff:9 rtt:0.866/0.944 ato:40 mss:65483 pmtu:65535 rcvmss:65483
>>>>> advmss:65483 cwnd:10 bytes_sent:36941001 bytes_retrans:22025 bytes_acked:31729223 bytes_received:228063971 segs_out:20136 segs_in:17497 data_segs_out:11971
>>>>> data_segs_in:16642 send 6049237875bps lastsnd:2663 lastrcv:136933 lastack:136944 pacing_rate 12093239064bps delivery_rate 130966000000bps delivered:11863
>>>>> app_limited busy:287561ms rwnd_limited:21ms(0.0%) retrans:0/2 dsack_dups:2 rcv_rtt:0.671 rcv_space:1793073 rcv_ssthresh:934517 notsent:222208 minrtt:0.013
>>>>> ESTAB       0            0 192.168.200.34:4004 192.168.200.34:16906
>>>>>           skmem:(r0,rb19521831,t0,tb2626560,f0,w0,o0,bl0,d0) ts sack reno wscale:10,10 rto:201 rtt:0.483/0.64 ato:40 mss:22016 pmtu:65535 rcvmss:65483 
>>>>> advmss:65483
>>>>> cwnd:5 ssthresh:5 bytes_sent:8175956 bytes_retrans:460 bytes_acked:8174668 bytes_received:20820708 segs_out:3635 segs_in:2491 data_segs_out:2377
>>>>> data_segs_in:2330 send 1823271222bps lastsnd:136934 lastrcv:136931 lastack:136932 pacing_rate 2185097952bps delivery_rate 70451200000bps delivered:2372
>>>>> busy:14988ms rwnd_limited:1ms(0.0%) retrans:0/5 rcv_rtt:1.216 rcv_space:779351 rcv_ssthresh:9759798 minrtt:0.003
>>>>> ESTAB       0            139656 192.168.200.34:16908 192.168.200.34:4004 timer:(persist,1min40sec,2)
>>>>> skmem:(r0,rb2000000,t0,tb2000000,f3960,w143496,o0,bl0,d0) ts sack reno wscale:10,10 rto:37397 backoff:2 rtt:4182.62/8303.35 ato:40 mss:65483 pmtu:65535
>>>>> rcvmss:22016 advmss:65483 cwnd:10 bytes_sent:22351275 bytes_retrans:397320 bytes_acked:20703982 bytes_received:7815946 segs_out:2585 segs_in:3642
>>>>> data_segs_out:2437 data_segs_in:2355 send 1252479bps lastsnd:19146 lastrcv:136931 lastack:136934 pacing_rate 2504952bps delivery_rate 15992bps delivered:2357
>>>>> busy:282917ms retrans:0/19 rcv_rtt:0.004 rcv_space:288293 rcv_ssthresh:43690 notsent:139656 minrtt:0.004
>>>>> ESTAB       0            460 192.168.200.34:4004 192.168.200.34:16908 timer:(on,1min11sec,9)
>>>>> skmem:(r0,rb9433368,t0,tb2626560,f2356,w1740,o0,bl0,d0) ts sack reno wscale:10,10 rto:102912 backoff:9 rtt:0.741/1.167 ato:40 mss:22016 pmtu:65535
>>>>> rcvmss:65483 advmss:65483 cwnd:1 ssthresh:2 bytes_sent:7850211 bytes_retrans:33437 bytes_acked:7815486 bytes_received:20703981 segs_out:3672 segs_in:2504
>>>>> data_segs_out:2380 data_segs_in:2356 send 237689609bps lastsnd:31434 lastrcv:169681 lastack:136931 pacing_rate 854817384bps delivery_rate 115645432bps
>>>>> delivered:2355 busy:212674ms unacked:1 retrans:0/24 lost:1 rcv_rtt:1.439 rcv_space:385874 rcv_ssthresh:4715943 minrtt:0.003
>>>>> ESTAB       0            147205 192.168.200.34:16906 192.168.200.34:4004 timer:(persist,1min35sec,9)
>>>>> skmem:(r0,rb2000000,t0,tb2000000,f507,w151045,o0,bl0,d0) ts sack reno wscale:10,10 rto:223 backoff:9 rtt:11.4/18.962 ato:40 mss:65483 pmtu:65535 rcvmss:22016
>>>>> advmss:65483 cwnd:10 bytes_sent:23635760 bytes_retrans:220124 bytes_acked:20820709 bytes_received:8174668 segs_out:2570 segs_in:3625 data_segs_out:2409
>>>>> data_segs_in:2371 send 459529825bps lastsnd:19146 lastrcv:136934 lastack:136931 pacing_rate 918999184bps delivery_rate 43655333328bps delivered:2331 
>>>>> app_limited
>>>>> busy:196996ms retrans:0/14 rcv_rtt:0.005 rcv_space:220160 rcv_ssthresh:43690 notsent:147205 minrtt:0.003
>>>>> ESTAB       0            3928980 127.0.0.1:4004 127.0.0.1:57224 timer:(persist,1min57sec,9)
>>>>> skmem:(r0,rb50000000,t0,tb3939840,f108,w4005780,o0,bl0,d3) ts sack reno wscale:4,10 rto:251 backoff:9 rtt:13.281/25.84 ato:40 mss:65483 pmtu:65535
>>>>> rcvmss:65483 advmss:65483 cwnd:10 ssthresh:10 bytes_sent:312488262 bytes_retrans:245567 bytes_acked:228063971 bytes_received:31729222 segs_out:18945
>>>>> segs_in:20021 data_segs_out:18091 data_segs_in:11862 send 394446201bps lastsnd:2762 lastrcv:136952 lastack:136933 pacing_rate 709983112bps delivery_rate
>>>>> 104772800000bps delivered:16643 app_limited busy:382149ms rwnd_limited:127ms(0.0%) retrans:0/26 rcv_rtt:7666.22 rcv_space:2279928 rcv_ssthresh:24999268
>>>>> notsent:3928980 minrtt:0.003
>>>>> [root@...23c-0bdd ~]#
>>>>>
>>>>>
>>>>> We can reproduce this readily at current, and I'm happy to try patches and/or do more debugging.  We also tried with a 5.12 kernel,
>>>>> and saw same problems, but in all cases, we have local patches applied, and there is no way for us to do this test without
>>>>> at least a fair bit of local patches applied.
>>>>
>>>> Thanks for the ss traces and tcpdump output! The tcpdump traces are
>>>> nice, in that they start before the connection starts, so capture the
>>>> SYN and its critical options like wscale.
>>>>
>>>>  From the "timer:(persist" in the ss output, it seems the stalls (that
>>>> are preventing the send buffers from being transmitted) are caused by
>>>> a 0-byte receive window causing the senders to stop sending, and
>>>> periodically fire the ICSK_TIME_PROBE0 timer to check for an open
>>>> receive window. From "backoff:9" it seems this condition has lasted
>>>> for a very long exponential backoff process.
>>>>
>>>> I don't see 0-byte receive window problems in the trace, but this is
>>>> probably because the tcpdump traces only last through 10:12:47 PST,
>>>> and the problem is showing up in ss at 10:14:49 AM PST and later.
>>>>
>>>> Is it possible to reproduce the problem again, and this time let the
>>>> tcpdump traces run all the way through the period where the
>>>> connections freeze and you grab the "ss" output?
>>>>
>>>> You may also have to explicitly kill the tcpdump. Perhaps the tail of
>>>> the trace was buffered in tcpdump's output buffer and not flushed to
>>>> disk. A "killall tcpdump" should do the trick to force it to cleanly
>>>> flush everything.
>>>
>>> Here is another set of debugging, I made sure tcpdump ran the entire time,
>>> as well as the ss monitoring script.
>>>
>>> http://www.candelatech.com/downloads/ss_log.txt
>>> http://www.candelatech.com/downloads/trace-lo-4004-b.pcap
>>>
>>> In addition, here are logs from my tool with msec timestamps. It is detecting
>>> communication failure and logging about it.  Interestingly, I think it recovered
>>> after one long timeout, but in the end, it went past the 2-minute cutoff mark
>>> where my program will close the TCP connection and restart things.
>>>
>>> 1641506767983:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 34458ms, sending req for update, read-isset: 0
>>> 1641506773839:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 40314ms, sending req for update, read-isset: 0
>>> 1641506780563:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 47038ms, sending req for update, read-isset: 0
>>> 1641506786567:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 53041ms, sending req for update, read-isset: 0
>>> 1641506823537:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 34949ms, sending req for update, read-isset: 0
>>> 1641506829280:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 40692ms, sending req for update, read-isset: 0
>>> 1641506834878:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 46289ms, sending req for update, read-isset: 0
>>> 1641506840778:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 52189ms, sending req for update, read-isset: 0
>>> 1641506846786:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 58198ms, sending req for update, read-isset: 0
>>> 1641506852746:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 64158ms, sending req for update, read-isset: 0
>>> 1641506858280:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 69692ms, sending req for update, read-isset: 0
>>> 1641506864200:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 75612ms, sending req for update, read-isset: 0
>>> 1641506870556:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 81968ms, sending req for update, read-isset: 0
>>> 1641506876564:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 87976ms, sending req for update, read-isset: 0
>>> 1641506882774:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 94185ms, sending req for update, read-isset: 0
>>>
>>> # Recovered between here and above it seems.
>>>
>>> 1641507005029:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 35840ms, sending req for update, read-isset: 0
>>> 1641507035759:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 30164ms, sending req for update, read-isset: 0
>>> 1641507042161:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 36565ms, sending req for update, read-isset: 0
>>> 1641507048397:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 42802ms, sending req for update, read-isset: 0
>>> 1641507054491:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 48896ms, sending req for update, read-isset: 0
>>> 1641507060748:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 55153ms, sending req for update, read-isset: 0
>>> 1641507067083:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 61488ms, sending req for update, read-isset: 0
>>> 1641507073438:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 67842ms, sending req for update, read-isset: 0
>>> 1641507079638:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 74042ms, sending req for update, read-isset: 0
>>> 1641507085926:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 80330ms, sending req for update, read-isset: 0
>>> 1641507091788:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 86192ms, sending req for update, read-isset: 0
>>> 1641507098042:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 92447ms, sending req for update, read-isset: 0
>>> 1641507104283:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 98687ms, sending req for update, read-isset: 0
>>> 1641507110466:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 104871ms, sending req for update, read-isset: 0
>>> 1641507116381:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 110786ms, sending req for update, read-isset: 0
>>> 1641507123034:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 117439ms, sending req for update, read-isset: 0
>>> 1641507128975:  Card.cc 801: WARNING:  Card: Shelf: 1, Card: 1 has not received communication in: 123379ms, sending req for update, read-isset: 0
>>
>> Hello Neal,
>>
>> Do the new captures help any?
>>
>> From my own looking at things, it seems that the sniffer fails to get frames near when the problem
>> starts happening.  I am baffled as to how that can happen, especially since it seems to stop getting
>> packets from multiple different TCP connections (the sniffer filter would pick up some other loop-back
>> related connections to the same IP port).
>>
>> And, if I interpret the ss output properly, after the problem happens, the sockets still think they are
>> sending data.  I didn't check closely enough to see if the peer side thought it received it.
>>
>> We are going to try to reproduce w/out wifi, but not sure we'll have any luck with that.
>> We did test w/out VRF (using lots of ip rules instead), and similar problem was seen according to my
>> test team (I did not debug it in detail).
>>
>> Do you have any suggestions for how to debug this further?  I am happy to hack stuff into the
>> kernel if you have some suggested places to add debugging...
>>
>> Thanks,
>> Ben
>>
> These 2 packets (or lack of packets between them) are suspicious.
> 
> 14:06:28.294557 IP 127.0.0.1.4004 > 127.0.0.1.57234: Flags [.], seq 226598466:226663949, ack 31270804, win 24414, options [nop,nop,TS val 3325283657 ecr 
> 3325283657], length 65483
> 
> 14:08:04.143548 IP 127.0.0.1.57234 > 127.0.0.1.4004: Flags [P.], seq 31270804:31336287, ack 226663949, win 58408, options [nop,nop,TS val 3325379506 ecr 
> 3325283657], length 65483
> 
> 
> It looks like ACK for first packet is not sent, and packet is not retransmitted.
> 
> This could be a bug in conntrack (dropping rtx packets over loopback so pcap do not show the attempts),
> 
> or persistent memory allocation errors in __tcp_send_ack()
> 
> 
> Or this could be that the missing ACK packet was dropped by tcpdump.
> 
> Another suspicious sequence is:
> 
> 14:09:29.159816 IP 127.0.0.1.57234 > 127.0.0.1.4004: Flags [P.], seq 32608288:32609208, ack 265640849, win 58408, options [nop,nop,TS val 3325464522 ecr 
> 3325464521], length 920
> 
> 14:10:05.487756 IP 127.0.0.1.57234 > 127.0.0.1.4004: Flags [.], seq 32609208:32674691, ack 265640849, win 58408, options [nop,nop,TS val 3325500850 ecr 
> 3325464521], length 65483
> 
> 14:10:05.487762 IP 127.0.0.1.4004 > 127.0.0.1.57234: Flags [P.], seq 265640849:265706332, ack 32674691, win 24382, options [nop,nop,TS val 3325500850 ecr 
> 3325500850], length 65483
> 
> Same pattern here, missing ACK for 1st packet, and no retransmits.

Thanks for your insight as well.

I have not poked in the tcp stack much, certainly not recently.  Do you have any suggestions
for checking if conntrack is at fault?  For instance, could I run a command that would clear
all contrack entries and then see if it re-built them properly and recovered?

Or something like the 'ss' tool that would show enough debug to find problematic conntrack
entries?

Or, if nothing else, I was planning to try to add printk in the packet tx path, trying to match only for
frames to or from port 4004 and to/from 127.0.0.1.

Two captures in a row showed that packet capture stopped near time of the problem starting, so
I think it is probably not just some random packet-loss issue with the capture, but rather
a real symptom of the problem.

Thanks,
Ben


-- 
Ben Greear <greearb@...delatech.com>
Candela Technologies Inc  http://www.candelatech.com

Powered by blists - more mailing lists