Message-ID: <20180416204334.GA9219@localhost.localdomain>
Date:   Mon, 16 Apr 2018 17:43:34 -0300
From:   Marcelo Ricardo Leitner <marcelo.leitner@...il.com>
To:     Dominique Martinet <asmadeus@...ewreck.org>
Cc:     Eric Dumazet <eric.dumazet@...il.com>,
        Michal Kubecek <mkubecek@...e.cz>, netdev@...r.kernel.org,
        Florian Westphal <fw@...len.de>
Subject: Re: tcp hang when socket fills up ?

On Sat, Apr 14, 2018 at 03:55:15AM +0200, Dominique Martinet wrote:
> 16:49:26.724457 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 25134, win 646, options [nop,nop,TS val 1617129467 ecr 1313937599], length 0
> 16:49:26.726081 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 26508, win 669, options [nop,nop,TS val 1617129471 ecr 1313937599], length 0
> 16:49:26.726391 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 27882, win 691, options [nop,nop,TS val 1617129471 ecr 1313937601], length 0
> 16:49:26.726962 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 29256, win 714, options [nop,nop,TS val 1617129472 ecr 1313937601], length 0
> 16:49:26.727614 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 30630, win 737, options [nop,nop,TS val 1617129473 ecr 1313937602], length 0
> 16:49:26.728084 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 32004, win 759, options [nop,nop,TS val 1617129473 ecr 1313937602], length 0

[A] (packet above)

> 16:49:26.728507 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 59484:60858, ack 4190, win 307, options [nop,nop,TS val 1313937635 ecr 1617129473], length 1374
> 16:49:26.728511 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 60858:62232, ack 4190, win 307, options [nop,nop,TS val 1313937635 ecr 1617129473], length 1374
> 16:49:26.729531 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 33378, win 782, options [nop,nop,TS val 1617129475 ecr 1313937607], length 0
> 16:49:26.730002 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 34752, win 805, options [nop,nop,TS val 1617129475 ecr 1313937607], length 0
> 16:49:26.730340 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 62232:63606, ack 4190, win 307, options [nop,nop,TS val 1313937636 ecr 1617129473], length 1374
> 16:49:26.730344 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 63606:64980, ack 4190, win 307, options [nop,nop,TS val 1313937636 ecr 1617129473], length 1374
> 16:49:26.731398 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 64980:66354, ack 4190, win 307, options [nop,nop,TS val 1313937638 ecr 1617129473], length 1374
> 16:49:26.731402 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 66354:67728, ack 4190, win 307, options [nop,nop,TS val 1313937638 ecr 1617129473], length 1374
> 16:49:26.731634 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 36126, win 827, options [nop,nop,TS val 1617129476 ecr 1313937607], length 0
> 16:49:26.732955 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 67728:69102, ack 4190, win 307, options [nop,nop,TS val 1313937639 ecr 1617129473], length 1374
> 16:49:26.732963 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 69102:70476, ack 4190, win 307, options [nop,nop,TS val 1313937639 ecr 1617129473], length 1374
> 16:49:26.733956 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 37500, win 850, options [nop,nop,TS val 1617129476 ecr 1313937607], length 0
> 16:49:26.734242 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 38874, win 872, options [nop,nop,TS val 1617129477 ecr 1313937608], length 0
> 16:49:26.734653 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 40248, win 895, options [nop,nop,TS val 1617129478 ecr 1313937608], length 0
> 16:49:26.735042 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 70476:71850, ack 4190, win 307, options [nop,nop,TS val 1313937641 ecr 1617129473], length 1374
> 16:49:26.735046 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 71850:73224, ack 4190, win 307, options [nop,nop,TS val 1313937641 ecr 1617129473], length 1374
> 16:49:26.735334 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 41622, win 918, options [nop,nop,TS val 1617129478 ecr 1313937609], length 0
> 16:49:26.736005 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 42996, win 940, options [nop,nop,TS val 1617129478 ecr 1313937609], length 0
> 16:49:26.736402 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 73224:74598, ack 4190, win 307, options [nop,nop,TS val 1313937643 ecr 1617129473], length 1374
> 16:49:26.736408 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 74598:75972, ack 4190, win 307, options [nop,nop,TS val 1313937643 ecr 1617129473], length 1374
> 16:49:26.738561 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 44370, win 963, options [nop,nop,TS val 1617129482 ecr 1313937616], length 0
> 16:49:26.739539 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 45744, win 986, options [nop,nop,TS val 1617129482 ecr 1313937616], length 0
> 16:49:26.739882 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 47118, win 1008, options [nop,nop,TS val 1617129484 ecr 1313937617], length 0
> 16:49:26.740255 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 48492, win 1031, options [nop,nop,TS val 1617129484 ecr 1313937617], length 0
> 16:49:26.746756 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 49866, win 1053, options [nop,nop,TS val 1617129493 ecr 1313937627], length 0
> 16:49:26.747923 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 51240, win 1076, options [nop,nop,TS val 1617129494 ecr 1313937627], length 0
> 16:49:26.749083 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 52614, win 1099, options [nop,nop,TS val 1617129495 ecr 1313937629], length 0
> 16:49:26.750171 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 53988, win 1121, options [nop,nop,TS val 1617129496 ecr 1313937629], length 0
> 16:49:26.750808 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 55362, win 1144, options [nop,nop,TS val 1617129497 ecr 1313937629], length 0
> 16:49:26.754648 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 56736, win 1167, options [nop,nop,TS val 1617129500 ecr 1313937629], length 0
> 16:49:26.755985 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 58110, win 1189, options [nop,nop,TS val 1617129501 ecr 1313937630], length 0
> 16:49:26.758513 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 59484, win 1212, options [nop,nop,TS val 1617129502 ecr 1313937630], length 0
> 16:49:26.759096 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 60858, win 1234, options [nop,nop,TS val 1617129503 ecr 1313937635], length 0
> 16:49:26.759421 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 62232, win 1257, options [nop,nop,TS val 1617129503 ecr 1313937635], length 0
> 16:49:26.759755 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 63606, win 1280, options [nop,nop,TS val 1617129504 ecr 1313937636], length 0
> 16:49:26.760653 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 64980, win 1302, options [nop,nop,TS val 1617129505 ecr 1313937636], length 0
> 16:49:26.761453 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 66354, win 1325, options [nop,nop,TS val 1617129506 ecr 1313937638], length 0
> 16:49:26.762199 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 67728, win 1348, options [nop,nop,TS val 1617129507 ecr 1313937638], length 0
> 16:49:26.763547 IP <client public ip>.31872 > <server local ip>.13317: Flags [P.], seq 4190:4226, ack 67728, win 1348, options [nop,nop,TS val 1617129507 ecr 1313937638], length 36
> 16:49:26.763553 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 70476, win 1393, options [nop,nop,TS val 1617129508 ecr 1313937639], length 0
> 16:49:26.764298 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 73224, win 1438, options [nop,nop,TS val 1617129509 ecr 1313937641], length 0
> 16:49:26.764676 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 75972, win 1444, options [nop,nop,TS val 1617129510 ecr 1313937643], length 0
> 16:49:26.807754 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 75972:77346, ack 4190, win 307, options [nop,nop,TS val 1313937714 ecr 1617129473], length 1374
> 16:49:26.876467 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 77346, win 1444, options [nop,nop,TS val 1617129620 ecr 1313937714], length 0
> 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

Probably bogus retrans for conntrack, but OUTPUT is not filtered.

> 16:49:27.051791 IP <client public ip>.31872 > <server local ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617129762 ecr 1313937714], length 36
> 16:49:27.076444 IP <client public ip>.31872 > <server local ip>.13317: Flags [.], ack 77346, win 1444, options [nop,nop,TS val 1617129822 ecr 1313937714,nop,nop,sack 1 {32004:33378}], length 0

I guess the issue lies with the dup-sack here.

AFAIR Disabling timestamps also disables SACK, which would avoid the
issue as conntrack will not see these as they won't happen anymore.

Then it gets locked into a loopy behavior:

> 16:49:27.371182 IP <client public ip>.31872 > <server local ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617130018 ecr 1313937714], length 36

> 16:49:27.519862 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 32004:33378, ack 4190, win 307, options [nop,nop,TS val 1313938426 ecr 1617129473], length 1374
> 16:49:27.547662 IP <client public ip>.31872 > <server local 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.883372 IP <client public ip>.31872 > <server local ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617130530 ecr 1313937714], length 36

Cycle 1

> 16:49:28.511861 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 32004:33378, ack 4190, win 307, options [nop,nop,TS val 1313939418 ecr 1617129473], length 1374
> 16:49:28.538891 IP <client public ip>.31872 > <server local 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.907197 IP <client public ip>.31872 > <server local ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617131554 ecr 1313937714], length 36

Cycle 2

> 16:49:30.431864 IP <server local ip>.13317 > <client public ip>.31872: Flags [.], seq 32004:33378, ack 4190, win 307, options [nop,nop,TS val 1313941338 ecr 1617129473], length 1374
> 16:49:30.459127 IP <client public ip>.31872 > <server local 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.955388 IP <client public ip>.31872 > <server local ip>.13317: Flags [P.], seq 4190:4226, ack 77346, win 1444, options [nop,nop,TS val 1617133602 ecr 1313937714], length 36

Cycle 3...

Based on server RTO.

But I can't tell why packet [A] and subsequent packets from client
never made to the server's socket.

Powered by blists - more mailing lists