Message-ID: <20180417092044.2hxw4chrn2mpgsyh@unicorn.suse.cz>
Date:   Tue, 17 Apr 2018 11:20:44 +0200
From:   Michal Kubecek <mkubecek@...e.cz>
To:     netdev@...r.kernel.org
Cc:     Florian Westphal <fw@...len.de>,
        Marcelo Ricardo Leitner <marcelo.leitner@...il.com>,
        Eric Dumazet <eric.dumazet@...il.com>
Subject: Re: tcp hang when socket fills up ?

On Mon, Apr 16, 2018 at 10:28:11PM -0700, Eric Dumazet wrote:
> > I turned pr_debug on in tcp_in_window() for another try and it's a bit
> > mangled because the information on multiple lines and the function is
> > called in parallel but it looks like I do have some seq > maxend +1
> > 
> > Although it's weird, the maxend was set WAY earlier apparently?
> > Apr 17 11:13:14 res=1 sender end=1913287798 maxend=1913316998 maxwin=29312 receiver end=505004284 maxend=505033596 maxwin=29200
> > then window decreased drastically e.g. previous ack just before refusal:
> > Apr 17 11:13:53 seq=1913292311 ack=505007789+(0) sack=505007789+(0) win=284 end=1913292311
> > Apr 17 11:13:53 sender end=1913292311 maxend=1913331607 maxwin=284 scale=0 receiver end=505020155 maxend=505033596 maxwin=39296 scale=7
> 
> scale=0 is suspect.
> 
> Really if conntrack does not see SYN SYNACK packets, it should not
> make any window check, since windows can be scaled up to 14 :/

Hm... it doesn't seem to be the case here:

14.364038 tcp_in_window: START
14.364065 tcp_in_window: 
14.364090 seq=505004283 ack=0+(0) sack=0+(0) win=29200 end=505004284
14.364129 tcp_in_window: sender end=505004284 maxend=505004284 maxwin=29200 scale=7 receiver end=0 maxend=0 maxwin=0 scale=0
14.364158 tcp_in_window: 
14.364185 seq=505004283 ack=0+(0) sack=0+(0) win=29200 end=505004284
14.364210 tcp_in_window: sender end=505004284 maxend=505004284 maxwin=29200 scale=7 receiver end=0 maxend=0 maxwin=0 scale=0
14.364237 tcp_in_window: I=1 II=1 III=1 IV=1
14.364262 tcp_in_window: res=1 sender end=505004284 maxend=505004284 maxwin=29200 receiver end=0 maxend=29200 maxwin=0

looks like SYN packet

14.661682 tcp_in_window: START
14.661706 tcp_in_window: 
14.661731 seq=1913287797 ack=0+(0) sack=0+(0) win=29200 end=1913287798
14.661828 tcp_in_window: sender end=0 maxend=29200 maxwin=0 scale=0 receiver end=505004284 maxend=505004284 maxwin=29200 scale=7
14.661867 tcp_in_window: START
14.661893 tcp_in_window: 
14.661917 seq=1025597635 ack=1542862349+(0) sack=1542862349+(0) win=2414 end=1025597635
14.661942 tcp_in_window: START
14.661966 tcp_in_window: 
14.661993 tcp_in_window: sender end=1025597635 maxend=1025635103 maxwin=354378 scale=7 receiver end=1542862349 maxend=1543168175 maxwin=37504 scale=7
14.662020 seq=505004283 ack=1913287798+(0) sack=1913287798+(0) win=29200 end=505004284
14.662045 tcp_in_window: 
14.662072 seq=1025597635 ack=1542862349+(0) sack=1542862349+(0) win=2414 end=1025597635
14.662097 tcp_in_window: sender end=505004284 maxend=505004284 maxwin=29200 scale=7 receiver end=1913287798 maxend=1913287798 maxwin=29200 scale=7
14.662125 tcp_in_window: 
14.662150 tcp_in_window: sender end=1025597635 maxend=1025635103 maxwin=354378 scale=7 receiver end=1542862349 maxend=1543168175 maxwin=37504 scale=7
14.662175 seq=505004283 ack=1913287798+(0) sack=1913287798+(0) win=29200 end=505004284
14.662202 tcp_in_window: sender end=505004284 maxend=505004284 maxwin=29200 scale=7 receiver end=1913287798 maxend=1913287798 maxwin=29200 scale=7
14.662226 tcp_in_window: I=1 II=1 III=1 IV=1
14.662251 tcp_in_window: I=1 II=1 III=1 IV=1
14.662277 tcp_in_window: res=1 sender end=505004284 maxend=505004284 maxwin=29200 receiver end=1913287798 maxend=1913316998 maxwin=29200
14.662302 tcp_in_window: res=1 sender end=1025597635 maxend=1025635103 maxwin=354378 receiver end=1542862349 maxend=1543171341 maxwin=37504

SYNACK response and (dataless) ACK in the original direction, mixed with
an unrelated packet.

14.687411 tcp_in_window: START
14.687522 tcp_in_window: 
14.687570 seq=1913287798 ack=505004284+(0) sack=505004284+(0) win=229 end=1913287798
14.687619 tcp_in_window: sender end=1913287798 maxend=1913316998 maxwin=29200 scale=7 receiver end=505004284 maxend=505004284 maxwin=29200 scale=7
14.687659 tcp_in_window: 
14.687699 seq=1913287798 ack=505004284+(0) sack=505004284+(0) win=229 end=1913287798
14.687739 tcp_in_window: sender end=1913287798 maxend=1913316998 maxwin=29200 scale=7 receiver end=505004284 maxend=505004284 maxwin=29200 scale=7
14.687774 tcp_in_window: I=1 II=1 III=1 IV=1
14.687806 tcp_in_window: res=1 sender end=1913287798 maxend=1913316998 maxwin=29312 receiver end=505004284 maxend=505033596 maxwin=29200

ACK in the reply direction (no data). We still have scale=7 in both
directions.

14.688706 tcp_in_window: START
14.688733 tcp_in_window: 
14.688762 seq=1913287798 ack=505004284+(0) sack=505004284+(0) win=229 end=1913287819
14.688793 tcp_in_window: sender end=1913287798 maxend=1913316998 maxwin=29312 scale=7 receiver end=505004284 maxend=505033596 maxwin=29200 scale=7
14.688824 tcp_in_window: 
14.688852 seq=1913287798 ack=505004284+(0) sack=505004284+(0) win=229 end=1913287819
14.688882 tcp_in_window: sender end=1913287819 maxend=1913287819 maxwin=229 scale=0 receiver end=505004284 maxend=505033596 maxwin=29200 scale=7
14.688911 tcp_in_window: I=1 II=1 III=1 IV=1
14.688938 tcp_in_window: res=1 sender end=1913287819 maxend=1913287819 maxwin=229 receiver end=505004284 maxend=505033596 maxwin=29200

Data (21 bytes) packet in reply direction. And somewhere between the
first and second debugging print, we ended up with sender scale=0 and
that value is then preserved from now on.

The only place between the two debug prints where we could change only
one of the td_sender values are the two calls to tcp_options() but
neither should be called now unless I missed something. I'll try to
think about it some more.

Michal Kubecek

Powered by blists - more mailing lists