Message-ID: <20180414010907.GA11526@nautica>
Date:   Sat, 14 Apr 2018 10:09:07 +0900
From:   Dominique Martinet <asmadeus@...ewreck.org>
To:     Michal Kubecek <mkubecek@...e.cz>,
        Eric Dumazet <eric.dumazet@...il.com>
Cc:     netdev@...r.kernel.org
Subject: Re: tcp hang when socket fills up ?

Thank you for the replies,

Eric Dumazet wrote on Fri, Apr 13, 2018:
> There is no way a regular TCP stack (including linux) could send the following frame.
> 
> > 16:49:27.048760 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 32004:33378, ack 4190, win 307, options [nop,nop,TS val 1313937955 ecr 1617129473], length 1374
> 
> So something is mangling the packet, maybe NAT or something.


The pcap was produced on the server which emitted the frame, so it
should be exactly as the server intended it to be without any mangling
involved?
If you could point at what strikes you as odd I can check if the same
happened on other hang traces I might still have. Is it just that it
replays a very old seq?
(if it's odd wrt client packets, the same trace as captured on client is
at the end of this mail)



Michal Kubecek wrote on Fri, Apr 13, 2018:
> The way I read this, server doesn't see anything sent by client since
> some point shortly before the dump shown here starts (about 5ms). It
> keeps sending data until 16:49:26.807754 (seq 77346) and then keeps
> resending first (from its point of view) unacknowledged segment
> (32004:33378) in exponentially growing intervals and ignores replies
> from the client. Client apparently receives these retransmits and
> replies with dupack (with D-SACK for 32004:33378) and retransmits of its
> own first unacknowledged segment (4190:4226).

I have the same understanding.

> As we can see the client packets in the dump (which was taken on
> server), it would mean they are dropped after the point where packet
> socket would pass them to libpcap. That might be e.g. netfilter
> (conntrack?) or the IP/TCP code detecting them to be invalid for some
> reason (which is not obvious to me from the dump above).

In my second mail, I got as far as `tcp_ack`, where the replays didn't
get considered for ack because it was seen as having the same ack number
as the lastest seen. I'm not sure why it didn't get considered the first
time, I need to add more instrumentation.

> There are two strange points:
> 
> 1. While client apparently responds to all server retransmits, it does
> so with TSecr=1313937714 (matching server packet from 16:49:26.807754)
> rather than TSval of the packets it dupacks (1313937955 through
> 1313953050). This doesn't seem to follow the rules of RFC 7323
> Section 4.3.

I have a pcap of the same sequence on the client as well, and it does
get the packets with higher val= unchanged, so that might be something
to look at.
I'll post a similarily formated tcpdump output at the end of this mail,
the timestamps and verious numbers in the traces match with my original
mail.

> 2. Window size values in acks from client grow with each acked packet by
> 22-23 (which might be ~1400 with scaling factor of 64). I would rather
> expect advertised receive window to go down by 1374 with each received
> segment and to grow by bigger steps with each read()/recv() call from
> application.

I have a very poor understanding of this part of the protocol/code, but
I think the window grows when a socket starts receiving a bulk of data.
Given this hangs very fast, there were only individual small packets up
till this trace where data comes in quickly, and I think this might just
be window scaling?
I might very well be wrong though..


> We might get more insight if we saw the same connection on both sides.
> From what was presented here, my guess is that
> 
>   (1) received packets are dropped somewhere on server side (after they
>       are cloned for the packet socket)

I'd agree for received replays, but I don't get why the first time that
ack was received didn't work.

>   (2) there is something wrong either on client side or between the two
>       hosts (there is at least a NAT, IIUC)

My minimal reproducer involves the internet, so there is no telling what
is in the middle, but there is at least two NAT, and the connection is
established through two connect() calls with carefully crafted
source/destination ports if that makes a difference.
I've done a bit more fiddling with netem/tbf and a single nat but I
still can't reproduce it on a local network; I need to spend more time
trying as this is very frustrating because I don't control any of the
two NATs in the real case.

I don't think the NATs are culprits, though - looking at the traces I
don't see any reordering within a direction, missing packets or fiddling
with values so this seems fairly straightforward.

Here's the client-side traces. pcap files still available on request, if
you prefer to look at it in wireshark or another tool.

16:49:26.726793 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 40248:41622, ack 4190, win 307, options [nop,nop,TS val 1313937609 ecr 1617129440], length 1374
16:49:26.726798 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 41622, win 918, options [nop,nop,TS val 1617129478 ecr 1313937609], length 0
16:49:26.726802 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 41622:42996, ack 4190, win 307, options [nop,nop,TS val 1313937609 ecr 1617129440], length 1374
16:49:26.726807 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 42996, win 940, options [nop,nop,TS val 1617129478 ecr 1313937609], length 0
16:49:26.730611 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 42996:44370, ack 4190, win 307, options [nop,nop,TS val 1313937616 ecr 1617129456], length 1374
16:49:26.730619 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 44370, win 963, options [nop,nop,TS val 1617129482 ecr 1313937616], length 0
16:49:26.730835 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 44370:45744, ack 4190, win 307, options [nop,nop,TS val 1313937616 ecr 1617129456], length 1374
16:49:26.730847 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 45744, win 986, options [nop,nop,TS val 1617129482 ecr 1313937616], length 0
16:49:26.732371 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 45744:47118, ack 4190, win 307, options [nop,nop,TS val 1313937617 ecr 1617129456], length 1374
16:49:26.732383 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 47118, win 1008, options [nop,nop,TS val 1617129484 ecr 1313937617], length 0
16:49:26.732393 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 47118:48492, ack 4190, win 307, options [nop,nop,TS val 1313937617 ecr 1617129456], length 1374
16:49:26.732400 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 48492, win 1031, options [nop,nop,TS val 1617129484 ecr 1313937617], length 0
16:49:26.740896 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 48492:49866, ack 4190, win 307, options [nop,nop,TS val 1313937627 ecr 1617129464], length 1374
16:49:26.740910 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 49866, win 1053, options [nop,nop,TS val 1617129493 ecr 1313937627], length 0
16:49:26.742220 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 49866:51240, ack 4190, win 307, options [nop,nop,TS val 1313937627 ecr 1617129464], length 1374
16:49:26.742232 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 51240, win 1076, options [nop,nop,TS val 1617129494 ecr 1313937627], length 0
16:49:26.743463 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 51240:52614, ack 4190, win 307, options [nop,nop,TS val 1313937629 ecr 1617129466], length 1374
16:49:26.743476 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 52614, win 1099, options [nop,nop,TS val 1617129495 ecr 1313937629], length 0
16:49:26.744478 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 52614:53988, ack 4190, win 307, options [nop,nop,TS val 1313937629 ecr 1617129466], length 1374
16:49:26.744490 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 53988, win 1121, options [nop,nop,TS val 1617129496 ecr 1313937629], length 0
16:49:26.744975 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 53988:55362, ack 4190, win 307, options [nop,nop,TS val 1313937629 ecr 1617129466], length 1374
16:49:26.744982 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 55362, win 1144, options [nop,nop,TS val 1617129497 ecr 1313937629], length 0
16:49:26.748722 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 55362:56736, ack 4190, win 307, options [nop,nop,TS val 1313937629 ecr 1617129466], length 1374
16:49:26.748733 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 56736, win 1167, options [nop,nop,TS val 1617129500 ecr 1313937629], length 0
16:49:26.749615 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 56736:58110, ack 4190, win 307, options [nop,nop,TS val 1313937630 ecr 1617129467], length 1374
16:49:26.749627 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 58110, win 1189, options [nop,nop,TS val 1617129501 ecr 1313937630], length 0
16:49:26.750248 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 58110:59484, ack 4190, win 307, options [nop,nop,TS val 1313937630 ecr 1617129467], length 1374
16:49:26.750260 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 59484, win 1212, options [nop,nop,TS val 1617129502 ecr 1313937630], length 0
16:49:26.750968 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 59484:60858, ack 4190, win 307, options [nop,nop,TS val 1313937635 ecr 1617129473], length 1374
16:49:26.750980 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 60858, win 1234, options [nop,nop,TS val 1617129503 ecr 1313937635], length 0
16:49:26.751486 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 60858:62232, ack 4190, win 307, options [nop,nop,TS val 1313937635 ecr 1617129473], length 1374
16:49:26.751498 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 62232, win 1257, options [nop,nop,TS val 1617129503 ecr 1313937635], length 0
16:49:26.752095 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 62232:63606, ack 4190, win 307, options [nop,nop,TS val 1313937636 ecr 1617129473], length 1374
16:49:26.752107 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 63606, win 1280, options [nop,nop,TS val 1617129504 ecr 1313937636], length 0
16:49:26.752920 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 63606:64980, ack 4190, win 307, options [nop,nop,TS val 1313937636 ecr 1617129473], length 1374
16:49:26.752932 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 64980, win 1302, options [nop,nop,TS val 1617129505 ecr 1313937636], length 0
16:49:26.754573 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 64980:66354, ack 4190, win 307, options [nop,nop,TS val 1313937638 ecr 1617129473], length 1374
16:49:26.754585 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 66354, win 1325, options [nop,nop,TS val 1617129506 ecr 1313937638], length 0
16:49:26.755260 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 66354:67728, ack 4190, win 307, options [nop,nop,TS val 1313937638 ecr 1617129473], length 1374
16:49:26.755271 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 67728, win 1348, options [nop,nop,TS val 1617129507 ecr 1313937638], length 0
16:49:26.755493 IP <client local ip>.31872 > <server public ip>.13317: Flags [P.], seq 4190:4226, ack 67728, win 1348, options [nop,nop,TS val 1617129507 ecr 1313937638], length 36
16:49:26.756076 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 67728:69102, ack 4190, win 307, options [nop,nop,TS val 1313937639 ecr 1617129473], length 1374
16:49:26.756391 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 69102:70476, ack 4190, win 307, options [nop,nop,TS val 1313937639 ecr 1617129473], length 1374
16:49:26.756402 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 70476, win 1393, options [nop,nop,TS val 1617129508 ecr 1313937639], length 0
16:49:26.757020 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 70476:71850, ack 4190, win 307, options [nop,nop,TS val 1313937641 ecr 1617129473], length 1374
16:49:26.757349 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 71850:73224, ack 4190, win 307, options [nop,nop,TS val 1313937641 ecr 1617129473], length 1374
16:49:26.757360 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 73224, win 1438, options [nop,nop,TS val 1617129509 ecr 1313937641], length 0
16:49:26.757878 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 73224:74598, ack 4190, win 307, options [nop,nop,TS val 1313937643 ecr 1617129473], length 1374
16:49:26.758457 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 74598:75972, ack 4190, win 307, options [nop,nop,TS val 1313937643 ecr 1617129473], length 1374
16:49:26.758465 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 75972, win 1444, options [nop,nop,TS val 1617129510 ecr 1313937643], length 0
16:49:26.828268 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 75972:77346, ack 4190, win 307, options [nop,nop,TS val 1313937714 ecr 1617129473], length 1374
16:49:26.868867 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 77346, win 1444, options [nop,nop,TS val 1617129620 ecr 1313937714], length 0
16:49:27.010733 IP <client local ip>.31872 > <server public ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617129762 ecr 1313937714], length 36
16:49:27.070035 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 32004:33378, ack 4190, win 307, options [nop,nop,TS val 1313937955 ecr 1617129473], length 1374
16:49:27.070062 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 77346, win 1444, options [nop,nop,TS val 1617129822 ecr 1313937714,nop,nop,sack 1 {32004:33378}], length 0
16:49:27.266769 IP <client local ip>.31872 > <server public ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617130018 ecr 1313937714], length 36
16:49:27.540998 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 32004:33378, ack 4190, win 307, options [nop,nop,TS val 1313938426 ecr 1617129473], length 1374
16:49:27.541022 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 77346, win 1444, options [nop,nop,TS val 1617130293 ecr 1313937714,nop,nop,sack 1 {32004:33378}], length 0
16:49:27.778687 IP <client local ip>.31872 > <server public ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617130530 ecr 1313937714], length 36
16:49:28.532876 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 32004:33378, ack 4190, win 307, options [nop,nop,TS val 1313939418 ecr 1617129473], length 1374
16:49:28.532907 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 77346, win 1444, options [nop,nop,TS val 1617131285 ecr 1313937714,nop,nop,sack 1 {32004:33378}], length 0
16:49:28.802879 IP <client local ip>.31872 > <server public ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617131554 ecr 1313937714], length 36
16:49:30.452830 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 32004:33378, ack 4190, win 307, options [nop,nop,TS val 1313941338 ecr 1617129473], length 1374
16:49:30.452861 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 77346, win 1444, options [nop,nop,TS val 1617133204 ecr 1313937714,nop,nop,sack 1 {32004:33378}], length 0
16:49:30.850734 IP <client local ip>.31872 > <server public ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617133602 ecr 1313937714], length 36
16:49:34.229420 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 32004:33378, ack 4190, win 307, options [nop,nop,TS val 1313945114 ecr 1617129473], length 1374
16:49:34.229447 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 77346, win 1444, options [nop,nop,TS val 1617136981 ecr 1313937714,nop,nop,sack 1 {32004:33378}], length 0
16:49:35.202854 IP <client local ip>.31872 > <server public ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617137954 ecr 1313937714], length 36
16:49:42.165044 IP <server public ip>.13317 > <client local ip>.31872: Flags [.], seq 32004:33378, ack 4190, win 307, options [nop,nop,TS val 1313953050 ecr 1617129473], length 1374
16:49:42.165073 IP <client local ip>.31872 > <server public ip>.13317: Flags [.], ack 77346, win 1444, options [nop,nop,TS val 1617144917 ecr 1313937714,nop,nop,sack 1 {32004:33378}], length 0
16:49:43.394773 IP <client local ip>.31872 > <server public ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617146146 ecr 1313937714], length 36


Once again, thank you both.
-- 
Dominique Martinet | Asmadeus

Powered by blists - more mailing lists