All of lore.kernel.org
 help / color / mirror / Atom feed
* Re: 3-way handshake sets conntrack timeout to max_retrans
       [not found] <alpine.LNX.2.21.1907100147540.26040@kich.toxcorp.com>
@ 2019-07-10 10:46 ` Jozsef Kadlecsik
  2019-07-10 10:54   ` Jakub Jankowski
  0 siblings, 1 reply; 6+ messages in thread
From: Jozsef Kadlecsik @ 2019-07-10 10:46 UTC (permalink / raw)
  To: Jakub Jankowski; +Cc: netfilter, mhemsley, netfilter-devel

Hi,

On Wed, 10 Jul 2019, Jakub Jankowski wrote:

> We're debugging a weird issue. tl;dr: I have a .pcap file of connection 
> setup that makes conntrack apply TCP_CONNTRACK_RETRANS timeout (300s by 
> default) instead of TCP_CONNTRACK_ESTABLISHED (5d by default). The .pcap 
> is a recording of some app traffic running on Windows (SAP, I believe).
> 
> To reproduce it, I set up a testbed consisting of three Debian (Buster) 
> VMs, running their default kernel (4.19.0-5-amd64, based on 4.19.37), 
> but I get the same results on vanilla 4.19.57.
> 
> 
>              10.88.15.142        10.88.15.1
>    ------------- enp0s3        enp0s3 -------------
>    |           | -------------------- |           |
>    | testhost1 |                      | testhost0 |
>    |           | -------------------- |    (DUT)  |
>    ------------- enp0s4        enp0s4 -------------
>              10.88.1.2           10.88.1.1
> 
> 
> Replaying "bad" pcap using tcpreplay from testhost1:
> 
> root@testhost1:~# tcpreplay --cachefile=replay.cache --intf1=enp0s4
> --intf2=enp0s3 -L 3 replay-timeadjusted.pcap
> 
> and capturing what is seen on Device Under Test (testhost0)
> 
> root@testhost0:~# tcpdump -s 0 -w replay-timeadjusted.pcap -i enp0s3 -nn
> 
> 
> To pinpoint which timeout is getting set, we slightly moved these two sysctls
> apart, because by default they're both 300s:
> 
> # sysctl -w net.netfilter.nf_conntrack_tcp_timeout_max_retrans=313
> # sysctl -w net.netfilter.nf_conntrack_tcp_timeout_unacknowledged=338
> 
> 
> Firewall setup is the simplest thing we could come up with for conntrack to
> handle this connection (and only this, to avoide pr_debug() noise):
> 
> root@testhost0:~# iptables-save
> # Generated by xtables-save v1.8.2 on Wed Jul 10 00:23:12 2019
> *filter
> :INPUT ACCEPT [0:0]
> :FORWARD ACCEPT [0:0]
> :OUTPUT ACCEPT [0:0]
> :fwd - [0:0]
> -A FORWARD -p tcp -m tcp --dport 3230 -j fwd
> -A FORWARD -p tcp -m tcp --sport 3230 -j fwd
> -A fwd -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT
> -A fwd -p tcp -m conntrack --ctstate NEW -m tcp --dport 3230 -j ACCEPT
> COMMIT
> # Completed on Wed Jul 10 00:23:12 2019
> root@testhost0:~#
> 
> 
> The offending handshake is:
> 
> root@testhost0:~# tcpdump -v -nn --absolute-tcp-sequence-numbers -r
> replayed-traffic.pcap
> reading from file replayed-traffic.pcap, link-type EN10MB (Ethernet)
> 01:13:25.070622 IP (tos 0x0, ttl 128, id 35410, offset 0, flags [DF], proto
> TCP (6), length 52)
>     10.88.15.142.51451 > 10.88.1.2.3230: Flags [S], cksum 0x1473 (correct),
> seq 962079611, win 64240, options [mss 1460,nop,wscale 8,nop,nop,sackOK],
> length 0
> 01:13:26.070462 IP (tos 0x0, ttl 53, id 29815, offset 0, flags [DF], proto TCP
> (6), length 48)
>     10.88.1.2.3230 > 10.88.15.142.51451: Flags [S.], cksum 0x70cf (correct),
> seq 1148284782, ack 962079612, win 65535, options [mss 1380,nop,wscale 3],
> length 0
> 01:13:27.070449 IP (tos 0x0, ttl 128, id 35411, offset 0, flags [DF], proto
> TCP (6), length 40)
>     10.88.15.142.51451 > 10.88.1.2.3230: Flags [.], cksum 0x9a46 (correct),
> ack 1148284783, win 512, length 0
> 
> This conversation results in the following conntrack events:
> 
> root@testhost0:~# conntrack -E --orig-src 10.88.15.142
>     [NEW] tcp      6 120 SYN_SENT src=10.88.15.142 dst=10.88.1.2 sport=51451
> dport=3230 [UNREPLIED] src=10.88.1.2 dst=10.88.15.142 sport=3230 dport=51451
>  [UPDATE] tcp      6 60 SYN_RECV src=10.88.15.142 dst=10.88.1.2 sport=51451
> dport=3230 src=10.88.1.2 dst=10.88.15.142 sport=3230 dport=51451
>  [UPDATE] tcp      6 312 ESTABLISHED src=10.88.15.142 dst=10.88.1.2
> sport=51451 dport=3230 src=10.88.1.2 dst=10.88.15.142 sport=3230 dport=51451
> [ASSURED]
> 
> 
> After enabling all pr_debug()s in nf_conntrack_proto_tcp.c, the above
> handshake results in this:
> 
> root@testhost0:~# grep 'Jul 10 00:55:01' /var/log/kern.log
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264058] tcp_new: sender
> end=1483803195 maxend=1483803195 maxwin=29200 scale=7 receiver end=0 maxend=0
> maxwin=0 scale=0
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264115] tcp_in_window: START
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264132] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264157] seq=1483803194 ack=0+(0)
> sack=0+(0) win=29200 end=1483803195
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264174] tcp_in_window: sender
> end=1483803195 maxend=1483803195 maxwin=29200 scale=7 receiver end=0 maxend=0
> maxwin=0 scale=0
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264184] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264197] seq=1483803194 ack=0+(0)
> sack=0+(0) win=29200 end=1483803195
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264210] tcp_in_window: sender
> end=1483803195 maxend=1483803195 maxwin=29200 scale=7 receiver end=0 maxend=0
> maxwin=0 scale=0
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264235] tcp_in_window: I=1 II=1 III=1
> IV=1
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264257] tcp_in_window: res=1 sender
> end=1483803195 maxend=1483803195 maxwin=29200 receiver end=0 maxend=29200
> maxwin=0
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264267] tcp_conntracks:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264280] syn=1 ack=0 fin=0 rst=0 old=0
> new=1
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265226] tcp_in_window: START
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265254] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265275] seq=3233541593
> ack=1483803195+(0) sack=1483803195+(0) win=28960 end=3233541594
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265295] tcp_in_window: sender end=0
> maxend=29200 maxwin=0 scale=0 receiver end=1483803195 maxend=1483803195
> maxwin=29200 scale=7
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265306] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265323] seq=3233541593
> ack=1483803195+(0) sack=1483803195+(0) win=28960 end=3233541594
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265338] tcp_in_window: sender
> end=3233541594 maxend=3233541594 maxwin=28960 scale=7 receiver end=1483803195
> maxend=1483803195 maxwin=29200 scale=7
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265350] tcp_in_window: I=1 II=1 III=1
> IV=1
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265366] tcp_in_window: res=1 sender
> end=3233541594 maxend=3233541594 maxwin=28960 receiver end=1483803195
> maxend=1483832155 maxwin=29200
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265395] tcp_conntracks:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265408] syn=1 ack=1 fin=0 rst=0 old=1
> new=2
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266310] tcp_in_window: START
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266348] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266365] seq=1483803195
> ack=3233541594+(0) sack=3233541594+(0) win=229 end=1483803195
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266380] tcp_in_window: sender
> end=1483803195 maxend=1483832155 maxwin=29200 scale=7 receiver end=3233541594
> maxend=3233541594 maxwin=28960 scale=7
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266391] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266405] seq=1483803195
> ack=3233541594+(0) sack=3233541594+(0) win=229 end=1483803195
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266419] tcp_in_window: sender
> end=1483803195 maxend=1483832155 maxwin=29200 scale=7 receiver end=3233541594
> maxend=3233541594 maxwin=28960 scale=7
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266432] tcp_in_window: I=1 II=1 III=1
> IV=1
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266458] tcp_in_window: res=1 sender
> end=1483803195 maxend=1483832155 maxwin=29312 receiver end=3233541594
> maxend=3233570906 maxwin=28960
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266471] tcp_conntracks:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266485] syn=0 ack=1 fin=0 rst=0 old=2
> new=3
> root@testhost0:~#

Thanks for the thorough report, but the kernel debug log above does not 
correspond to the packet replay: the TCP parameters do not match. Please 
send the proper debug log, so we can look into it.

Best regards,
Jozsef
 
> Why would ESTABLISHED state's timeout be set to TCP_CONNTRACK_RETRANS?
> We know that it's getting into this elseif clause:
> https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/tree/net/netfilter/nf_conntrack_proto_tcp.c?h=linux-4.19.y#n1060
> 
> 	else if (ct->proto.tcp.last_win == 0 &&
> 		 timeouts[new_state] > timeouts[TCP_CONNTRACK_RETRANS])
> 		timeout = timeouts[TCP_CONNTRACK_RETRANS];
> 
> Which was added in commit fbcd253d2448b8f168241e38f629a36c4c8c1e94
> ("netfilter: conntrack: lower timeout to RETRANS seconds if window is 0")
> And indeed - reverting this commit makes the behaviour go away, timeout is set
> to default 5 days.
> 
> 
> This must be something specific to these three packets, or (less likely) to
> the way tcpreplay works, as I repeated a similar test, adding third host (also
> Debian Buster) and doing plain netcat+telnet via DUT:
> 
> 
>        10.88.15.142      10.88.15.1
>    -------------            -------------------
>    | testhost1 | ---------- | testhost0 (DUT) |
>    -------------            -------------------
>                                 |  10.5.5.1
>                                 |
>                                 |
>                                 |
>                                 |  10.5.5.82
>                             -------------
>                             | testhost2 |
>                             -------------
> 
> Setting up simple netcat server listening on testhost2, and running "telnet
> testhost2 3230" from testhost1:
> 
> root@testhost2:~# ./prep.sh
> + ip route add 10.88.15.0/24 via 10.5.5.1
> root@testhost2:~# nc -l -p 3230
> 
> 
> root@testhost1:~# ./prep.sh
> + ip route add 10.5.5.0/24 via 10.88.15.1
> root@testhost1:~# telnet 10.5.5.82 3230
> Trying 10.5.5.82...
> Connected to 10.5.5.82.
> Escape character is '^]'.
> 
> 
> This produced the following handshake:
> 
> root@testhost0:~# tcpdump -v -nn --absolute-tcp-sequence-numbers -r
> regular-telnet.pcap
> reading from file regular-telnet.pcap, link-type EN10MB (Ethernet)
> 00:55:01.317397 IP (tos 0x10, ttl 64, id 9367, offset 0, flags [DF], proto TCP
> (6), length 60)
>     10.88.15.142.59416 > 10.5.5.82.3230: Flags [S], cksum 0x296b (incorrect ->
> 0xd691), seq 1483803194, win 29200, options [mss 1460,sackOK,TS val 1611079352
> ecr 0,nop,wscale 7], length 0
> 00:55:01.318858 IP (tos 0x0, ttl 63, id 0, offset 0, flags [DF], proto TCP
> (6), length 60)
>     10.5.5.82.3230 > 10.88.15.142.59416: Flags [S.], cksum 0x296b (incorrect
> -> 0xd584), seq 3233541593, ack 1483803195, win 28960, options [mss
> 1460,sackOK,TS val 3393620239 ecr 1611079352,nop,wscale 7], length 0
> 00:55:01.319663 IP (tos 0x10, ttl 64, id 9368, offset 0, flags [DF], proto TCP
> (6), length 52)
>     10.88.15.142.59416 > 10.5.5.82.3230: Flags [.], cksum 0x2963 (incorrect ->
> 0x748a), ack 3233541594, win 229, options [nop,nop,TS val 1611079354 ecr
> 3393620239], length 0
> root@testhost0:~#
> 
> And conntrack timeout is also as expected:
> 
> root@testhost0:~# conntrack -E --orig-src 10.88.15.142
>     [NEW] tcp      6 120 SYN_SENT src=10.88.15.142 dst=10.5.5.82 sport=59416
> dport=3230 [UNREPLIED] src=10.5.5.82 dst=10.88.15.142 sport=3230 dport=59416
>  [UPDATE] tcp      6 60 SYN_RECV src=10.88.15.142 dst=10.5.5.82 sport=59416
> dport=3230 src=10.5.5.82 dst=10.88.15.142 sport=3230 dport=59416
>  [UPDATE] tcp      6 432000 ESTABLISHED src=10.88.15.142 dst=10.5.5.82
> sport=59416 dport=3230 src=10.5.5.82 dst=10.88.15.142 sport=3230 dport=59416
> [ASSURED]
> 
> 
> pr_debug()s from this "telnet" handshake are:
> 
> root@testhost0:~# grep 'Jul 10 00:55:01' /var/log/kern.log
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264058] tcp_new: sender
> end=1483803195 maxend=1483803195 maxwin=29200 scale=7 receiver end=0 maxend=0
> maxwin=0 scale=0
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264115] tcp_in_window: START
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264132] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264157] seq=1483803194 ack=0+(0)
> sack=0+(0) win=29200 end=1483803195
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264174] tcp_in_window: sender
> end=1483803195 maxend=1483803195 maxwin=29200 scale=7 receiver end=0 maxend=0
> maxwin=0 scale=0
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264184] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264197] seq=1483803194 ack=0+(0)
> sack=0+(0) win=29200 end=1483803195
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264210] tcp_in_window: sender
> end=1483803195 maxend=1483803195 maxwin=29200 scale=7 receiver end=0 maxend=0
> maxwin=0 scale=0
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264235] tcp_in_window: I=1 II=1 III=1
> IV=1
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264257] tcp_in_window: res=1 sender
> end=1483803195 maxend=1483803195 maxwin=29200 receiver end=0 maxend=29200
> maxwin=0
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264267] tcp_conntracks:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.264280] syn=1 ack=0 fin=0 rst=0 old=0
> new=1
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265226] tcp_in_window: START
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265254] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265275] seq=3233541593
> ack=1483803195+(0) sack=1483803195+(0) win=28960 end=3233541594
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265295] tcp_in_window: sender end=0
> maxend=29200 maxwin=0 scale=0 receiver end=1483803195 maxend=1483803195
> maxwin=29200 scale=7
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265306] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265323] seq=3233541593
> ack=1483803195+(0) sack=1483803195+(0) win=28960 end=3233541594
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265338] tcp_in_window: sender
> end=3233541594 maxend=3233541594 maxwin=28960 scale=7 receiver end=1483803195
> maxend=1483803195 maxwin=29200 scale=7
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265350] tcp_in_window: I=1 II=1 III=1
> IV=1
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265366] tcp_in_window: res=1 sender
> end=3233541594 maxend=3233541594 maxwin=28960 receiver end=1483803195
> maxend=1483832155 maxwin=29200
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265395] tcp_conntracks:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.265408] syn=1 ack=1 fin=0 rst=0 old=1
> new=2
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266310] tcp_in_window: START
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266348] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266365] seq=1483803195
> ack=3233541594+(0) sack=3233541594+(0) win=229 end=1483803195
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266380] tcp_in_window: sender
> end=1483803195 maxend=1483832155 maxwin=29200 scale=7 receiver end=3233541594
> maxend=3233541594 maxwin=28960 scale=7
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266391] tcp_in_window:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266405] seq=1483803195
> ack=3233541594+(0) sack=3233541594+(0) win=229 end=1483803195
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266419] tcp_in_window: sender
> end=1483803195 maxend=1483832155 maxwin=29200 scale=7 receiver end=3233541594
> maxend=3233541594 maxwin=28960 scale=7
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266432] tcp_in_window: I=1 II=1 III=1
> IV=1
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266458] tcp_in_window: res=1 sender
> end=1483803195 maxend=1483832155 maxwin=29312 receiver end=3233541594
> maxend=3233570906 maxwin=28960
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266471] tcp_conntracks:
> Jul 10 00:55:01 testhost0 kernel: [ 1146.266485] syn=0 ack=1 fin=0 rst=0 old=2
> new=3
> root@testhost0:~#
> 
> 
> Any pointers are welcome :)
> 
> 
> Regards,
>  Jakub
> 
> 
> -- 
> Jakub Jankowski|shasta@toxcorp.com|https://toxcorp.com/
> 

-
E-mail  : kadlec@blackhole.kfki.hu, kadlecsik.jozsef@wigner.mta.hu
PGP key : http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address : Wigner Research Centre for Physics, Hungarian Academy of Sciences
          H-1525 Budapest 114, POB. 49, Hungary

^ permalink raw reply	[flat|nested] 6+ messages in thread
* Re: 3-way handshake sets conntrack timeout to max_retrans
  2019-07-10 10:46 ` 3-way handshake sets conntrack timeout to max_retrans Jozsef Kadlecsik
@ 2019-07-10 10:54   ` Jakub Jankowski
  2019-07-11  9:01     ` Jozsef Kadlecsik
  0 siblings, 1 reply; 6+ messages in thread
From: Jakub Jankowski @ 2019-07-10 10:54 UTC (permalink / raw)
  To: Jozsef Kadlecsik; +Cc: Jakub Jankowski, netfilter, mhemsley, netfilter-devel

On 2019-07-10, Jozsef Kadlecsik wrote:

> Hi,
>
> On Wed, 10 Jul 2019, Jakub Jankowski wrote:
>
>> We're debugging a weird issue. tl;dr: I have a .pcap file of connection
>> setup that makes conntrack apply TCP_CONNTRACK_RETRANS timeout (300s by
>> default) instead of TCP_CONNTRACK_ESTABLISHED (5d by default). The .pcap
>> is a recording of some app traffic running on Windows (SAP, I believe).
>>
>> To reproduce it, I set up a testbed consisting of three Debian (Buster)
>> VMs, running their default kernel (4.19.0-5-amd64, based on 4.19.37),
>> but I get the same results on vanilla 4.19.57.
>>
>>
>>              10.88.15.142        10.88.15.1
>>    ------------- enp0s3        enp0s3 -------------
>>    |           | -------------------- |           |
>>    | testhost1 |                      | testhost0 |
>>    |           | -------------------- |    (DUT)  |
>>    ------------- enp0s4        enp0s4 -------------
>>              10.88.1.2           10.88.1.1
>>
>>
>> Replaying "bad" pcap using tcpreplay from testhost1:
>>
>> root@testhost1:~# tcpreplay --cachefile=replay.cache --intf1=enp0s4
>> --intf2=enp0s3 -L 3 replay-timeadjusted.pcap
>>
>> and capturing what is seen on Device Under Test (testhost0)
>>
>> root@testhost0:~# tcpdump -s 0 -w replay-timeadjusted.pcap -i enp0s3 -nn
>>
>>
>> To pinpoint which timeout is getting set, we slightly moved these two sysctls
>> apart, because by default they're both 300s:
>>
>> # sysctl -w net.netfilter.nf_conntrack_tcp_timeout_max_retrans=313
>> # sysctl -w net.netfilter.nf_conntrack_tcp_timeout_unacknowledged=338
>>
>>
>> Firewall setup is the simplest thing we could come up with for conntrack to
>> handle this connection (and only this, to avoide pr_debug() noise):
>>
>> root@testhost0:~# iptables-save
>> # Generated by xtables-save v1.8.2 on Wed Jul 10 00:23:12 2019
>> *filter
>> :INPUT ACCEPT [0:0]
>> :FORWARD ACCEPT [0:0]
>> :OUTPUT ACCEPT [0:0]
>> :fwd - [0:0]
>> -A FORWARD -p tcp -m tcp --dport 3230 -j fwd
>> -A FORWARD -p tcp -m tcp --sport 3230 -j fwd
>> -A fwd -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT
>> -A fwd -p tcp -m conntrack --ctstate NEW -m tcp --dport 3230 -j ACCEPT
>> COMMIT
>> # Completed on Wed Jul 10 00:23:12 2019
>> root@testhost0:~#
>>
>>
>> The offending handshake is:
>>
>> root@testhost0:~# tcpdump -v -nn --absolute-tcp-sequence-numbers -r
>> replayed-traffic.pcap
>> reading from file replayed-traffic.pcap, link-type EN10MB (Ethernet)
>> 01:13:25.070622 IP (tos 0x0, ttl 128, id 35410, offset 0, flags [DF], proto
>> TCP (6), length 52)
>>     10.88.15.142.51451 > 10.88.1.2.3230: Flags [S], cksum 0x1473 (correct),
>> seq 962079611, win 64240, options [mss 1460,nop,wscale 8,nop,nop,sackOK],
>> length 0
>> 01:13:26.070462 IP (tos 0x0, ttl 53, id 29815, offset 0, flags [DF], proto TCP
>> (6), length 48)
>>     10.88.1.2.3230 > 10.88.15.142.51451: Flags [S.], cksum 0x70cf (correct),
>> seq 1148284782, ack 962079612, win 65535, options [mss 1380,nop,wscale 3],
>> length 0
>> 01:13:27.070449 IP (tos 0x0, ttl 128, id 35411, offset 0, flags [DF], proto
>> TCP (6), length 40)
>>     10.88.15.142.51451 > 10.88.1.2.3230: Flags [.], cksum 0x9a46 (correct),
>> ack 1148284783, win 512, length 0
>>
>> This conversation results in the following conntrack events:
>>
>> root@testhost0:~# conntrack -E --orig-src 10.88.15.142
>>     [NEW] tcp      6 120 SYN_SENT src=10.88.15.142 dst=10.88.1.2 sport=51451
>> dport=3230 [UNREPLIED] src=10.88.1.2 dst=10.88.15.142 sport=3230 dport=51451
>>  [UPDATE] tcp      6 60 SYN_RECV src=10.88.15.142 dst=10.88.1.2 sport=51451
>> dport=3230 src=10.88.1.2 dst=10.88.15.142 sport=3230 dport=51451
>>  [UPDATE] tcp      6 312 ESTABLISHED src=10.88.15.142 dst=10.88.1.2
>> sport=51451 dport=3230 src=10.88.1.2 dst=10.88.15.142 sport=3230 dport=51451
>> [ASSURED]
>>
>>
>> After enabling all pr_debug()s in nf_conntrack_proto_tcp.c, the above
>> handshake results in this:
>>
>
> Thanks for the thorough report, but the kernel debug log above does not
> correspond to the packet replay: the TCP parameters do not match. Please
> send the proper debug log, so we can look into it.

Argh. My bad, wrong copy&paste, sorry. Here goes the correct debug 
snippet:

Jul 10 01:13:25 testhost0 kernel: [ 2250.026592] tcp_new: sender end=962079612 maxend=962079612 maxwin=64240 scale=8 receiver end=0 maxend=0 maxwin=0 scale=0
Jul 10 01:13:25 testhost0 kernel: [ 2250.026632] tcp_in_window: START
Jul 10 01:13:25 testhost0 kernel: [ 2250.026640] tcp_in_window:
Jul 10 01:13:25 testhost0 kernel: [ 2250.026652] seq=962079611 ack=0+(0) sack=0+(0) win=64240 end=962079612
Jul 10 01:13:25 testhost0 kernel: [ 2250.026663] tcp_in_window: sender end=962079612 maxend=962079612 maxwin=64240 scale=8 receiver end=0 maxend=0 maxwin=0 scale=0
Jul 10 01:13:25 testhost0 kernel: [ 2250.026671] tcp_in_window:
Jul 10 01:13:25 testhost0 kernel: [ 2250.026680] seq=962079611 ack=0+(0) sack=0+(0) win=64240 end=962079612
Jul 10 01:13:25 testhost0 kernel: [ 2250.026690] tcp_in_window: sender end=962079612 maxend=962079612 maxwin=64240 scale=8 receiver end=0 maxend=0 maxwin=0 scale=0
Jul 10 01:13:25 testhost0 kernel: [ 2250.026698] tcp_in_window: I=1 II=1 III=1 IV=1
Jul 10 01:13:25 testhost0 kernel: [ 2250.026708] tcp_in_window: res=1 sender end=962079612 maxend=962079612 maxwin=64240 receiver end=0 maxend=64240 maxwin=0
Jul 10 01:13:25 testhost0 kernel: [ 2250.026715] tcp_conntracks:
Jul 10 01:13:25 testhost0 kernel: [ 2250.026725] syn=1 ack=0 fin=0 rst=0 old=0 new=1
Jul 10 01:13:26 testhost0 kernel: [ 2251.026365] tcp_in_window: START
Jul 10 01:13:26 testhost0 kernel: [ 2251.026373] tcp_in_window:
Jul 10 01:13:26 testhost0 kernel: [ 2251.026376] seq=1148284782 ack=962079612+(0) sack=962079612+(0) win=65535 end=1148284783
Jul 10 01:13:26 testhost0 kernel: [ 2251.026379] tcp_in_window: sender end=0 maxend=64240 maxwin=0 scale=0 receiver end=962079612 maxend=962079612 maxwin=64240 scale=8
Jul 10 01:13:26 testhost0 kernel: [ 2251.026380] tcp_in_window:
Jul 10 01:13:26 testhost0 kernel: [ 2251.026382] seq=1148284782 ack=962079612+(0) sack=962079612+(0) win=65535 end=1148284783
Jul 10 01:13:26 testhost0 kernel: [ 2251.026384] tcp_in_window: sender end=1148284783 maxend=1148284783 maxwin=65535 scale=3 receiver end=962079612 maxend=962079612 maxwin=64240 scale=8
Jul 10 01:13:26 testhost0 kernel: [ 2251.026386] tcp_in_window: I=1 II=1 III=1 IV=1
Jul 10 01:13:26 testhost0 kernel: [ 2251.026387] tcp_in_window: res=1 sender end=1148284783 maxend=1148284783 maxwin=65535 receiver end=962079612 maxend=962145147 maxwin=64240
Jul 10 01:13:26 testhost0 kernel: [ 2251.026389] tcp_conntracks:
Jul 10 01:13:26 testhost0 kernel: [ 2251.026391] syn=1 ack=1 fin=0 rst=0 old=1 new=2
Jul 10 01:13:27 testhost0 kernel: [ 2252.026425] tcp_in_window: START
Jul 10 01:13:27 testhost0 kernel: [ 2252.026435] tcp_in_window:
Jul 10 01:13:27 testhost0 kernel: [ 2252.026438] seq=962079612 ack=1148284783+(0) sack=1148284783+(0) win=512 end=962079612
Jul 10 01:13:27 testhost0 kernel: [ 2252.026440] tcp_in_window: sender end=962079612 maxend=962145147 maxwin=64240 scale=8 receiver end=1148284783 maxend=1148284783 maxwin=65535 scale=3
Jul 10 01:13:27 testhost0 kernel: [ 2252.026442] tcp_in_window:
Jul 10 01:13:27 testhost0 kernel: [ 2252.026444] seq=962079612 ack=1148284783+(0) sack=1148284783+(0) win=512 end=962079612
Jul 10 01:13:27 testhost0 kernel: [ 2252.026446] tcp_in_window: sender end=962079612 maxend=962145147 maxwin=64240 scale=8 receiver end=1148284783 maxend=1148284783 maxwin=65535 scale=3
Jul 10 01:13:27 testhost0 kernel: [ 2252.026447] tcp_in_window: I=1 II=1 III=1 IV=1
Jul 10 01:13:27 testhost0 kernel: [ 2252.026449] tcp_in_window: res=1 sender end=962079612 maxend=962145147 maxwin=131072 receiver end=1148284783 maxend=1148415855 maxwin=65535
Jul 10 01:13:27 testhost0 kernel: [ 2252.026451] tcp_conntracks:
Jul 10 01:13:27 testhost0 kernel: [ 2252.026452] syn=0 ack=1 fin=0 rst=0 old=2 new=3


J.

-- 
Jakub Jankowski|shasta@toxcorp.com|https://toxcorp.com/

^ permalink raw reply	[flat|nested] 6+ messages in thread
* Re: 3-way handshake sets conntrack timeout to max_retrans
  2019-07-10 10:54   ` Jakub Jankowski
@ 2019-07-11  9:01     ` Jozsef Kadlecsik
  2019-07-11  9:36       ` Jakub Jankowski
  0 siblings, 1 reply; 6+ messages in thread
From: Jozsef Kadlecsik @ 2019-07-11  9:01 UTC (permalink / raw)
  To: Jakub Jankowski; +Cc: netfilter, mhemsley, netfilter-devel

[-- Attachment #1: Type: text/plain, Size: 3020 bytes --]

Hi,

On Wed, 10 Jul 2019, Jakub Jankowski wrote:

> On 2019-07-10, Jozsef Kadlecsik wrote:
> 
> > On Wed, 10 Jul 2019, Jakub Jankowski wrote:
> > 
> > > We're debugging a weird issue. tl;dr: I have a .pcap file of connection
> > > setup that makes conntrack apply TCP_CONNTRACK_RETRANS timeout (300s by
> > > default) instead of TCP_CONNTRACK_ESTABLISHED (5d by default). The .pcap
> > > is a recording of some app traffic running on Windows (SAP, I believe).
> > >
> > > The offending handshake is:
> > > 
> > > root@testhost0:~# tcpdump -v -nn --absolute-tcp-sequence-numbers -r
> > > replayed-traffic.pcap
> > > reading from file replayed-traffic.pcap, link-type EN10MB (Ethernet)
> > > 01:13:25.070622 IP (tos 0x0, ttl 128, id 35410, offset 0, flags [DF],
> > > proto
> > > TCP (6), length 52)
> > >     10.88.15.142.51451 > 10.88.1.2.3230: Flags [S], cksum 0x1473
> > > (correct),
> > > seq 962079611, win 64240, options [mss 1460,nop,wscale 8,nop,nop,sackOK],
> > > length 0
> > > 01:13:26.070462 IP (tos 0x0, ttl 53, id 29815, offset 0, flags [DF], proto
> > > TCP
> > > (6), length 48)
> > >     10.88.1.2.3230 > 10.88.15.142.51451: Flags [S.], cksum 0x70cf
> > > (correct),
> > > seq 1148284782, ack 962079612, win 65535, options [mss 1380,nop,wscale 3],
> > > length 0
> > > 01:13:27.070449 IP (tos 0x0, ttl 128, id 35411, offset 0, flags [DF],
> > > proto
> > > TCP (6), length 40)
> > >     10.88.15.142.51451 > 10.88.1.2.3230: Flags [.], cksum 0x9a46
> > > (correct),
> > > ack 1148284783, win 512, length 0
> > > 
> > > This conversation results in the following conntrack events:
> > > 
> > > root@testhost0:~# conntrack -E --orig-src 10.88.15.142
> > >     [NEW] tcp      6 120 SYN_SENT src=10.88.15.142 dst=10.88.1.2
> > > sport=51451
> > > dport=3230 [UNREPLIED] src=10.88.1.2 dst=10.88.15.142 sport=3230
> > > dport=51451
> > >  [UPDATE] tcp      6 60 SYN_RECV src=10.88.15.142 dst=10.88.1.2
> > > sport=51451
> > > dport=3230 src=10.88.1.2 dst=10.88.15.142 sport=3230 dport=51451
> > >  [UPDATE] tcp      6 312 ESTABLISHED src=10.88.15.142 dst=10.88.1.2
> > > sport=51451 dport=3230 src=10.88.1.2 dst=10.88.15.142 sport=3230
> > > dport=51451
> > > [ASSURED]
> > > 
> > > 
> > > After enabling all pr_debug()s in nf_conntrack_proto_tcp.c, the above
> > > handshake results in this:
> > 
> > Thanks for the thorough report, but the kernel debug log above does not
> > correspond to the packet replay: the TCP parameters do not match. Please
> > send the proper debug log, so we can look into it.
> 
> Argh. My bad, wrong copy&paste, sorry. Here goes the correct debug snippet:

The kernel does not print enough information. Could you apply the attached 
patch to your kernel at the test machine, rerun the test and send the 
logs?

Best regards,
Jozsef
-
E-mail  : kadlec@blackhole.kfki.hu, kadlecsik.jozsef@wigner.mta.hu
PGP key : http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address : Wigner Research Centre for Physics, Hungarian Academy of Sciences
          H-1525 Budapest 114, POB. 49, Hungary

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: tcp_conntrack_debug.patch --]
[-- Type: text/x-diff; name=tcp_conntrack_debug.patch, Size: 1803 bytes --]

diff --git a/net/netfilter/nf_conntrack_proto_tcp.c b/net/netfilter/nf_conntrack_proto_tcp.c
index 37ef35b861f2..fecc20036882 100644
--- a/net/netfilter/nf_conntrack_proto_tcp.c
+++ b/net/netfilter/nf_conntrack_proto_tcp.c
@@ -526,11 +526,14 @@ static bool tcp_in_window(const struct nf_conn *ct,
 	pr_debug("seq=%u ack=%u+(%d) sack=%u+(%d) win=%u end=%u\n",
 		 seq, ack, receiver_offset, sack, receiver_offset, win, end);
 	pr_debug("tcp_in_window: sender end=%u maxend=%u maxwin=%u scale=%i "
-		 "receiver end=%u maxend=%u maxwin=%u scale=%i\n",
+		 "receiver end=%u maxend=%u maxwin=%u scale=%i "
+		 "last dir=%d seq=%u ack=%u end=%u win=%u retrans=%d\n",
 		 sender->td_end, sender->td_maxend, sender->td_maxwin,
 		 sender->td_scale,
 		 receiver->td_end, receiver->td_maxend, receiver->td_maxwin,
-		 receiver->td_scale);
+		 receiver->td_scale,
+		 state->last_dir, state->last_seq, state->last_ack,
+		 state->last_end, state->last_win, state->retrans);
 
 	if (sender->td_maxwin == 0) {
 		/*
@@ -715,10 +718,15 @@ static bool tcp_in_window(const struct nf_conn *ct,
 		}
 	}
 
-	pr_debug("tcp_in_window: res=%u sender end=%u maxend=%u maxwin=%u "
-		 "receiver end=%u maxend=%u maxwin=%u\n",
+	pr_debug("tcp_in_window: res=%u sender end=%u maxend=%u maxwin=%u scale=%i "
+		 "receiver end=%u maxend=%u maxwin=%u scale=%i "
+		 "last dir=%d seq=%u ack=%u end=%u win=%u retrans=%d\n",
 		 res, sender->td_end, sender->td_maxend, sender->td_maxwin,
-		 receiver->td_end, receiver->td_maxend, receiver->td_maxwin);
+		 sender->td_scale,
+		 receiver->td_end, receiver->td_maxend, receiver->td_maxwin,
+		 receiver->td_scale,
+		 state->last_dir, state->last_seq, state->last_ack,
+		 state->last_end, state->last_win, state->retrans);
 
 	return res;
 }

^ permalink raw reply related	[flat|nested] 6+ messages in thread
* Re: 3-way handshake sets conntrack timeout to max_retrans
  2019-07-11  9:01     ` Jozsef Kadlecsik
@ 2019-07-11  9:36       ` Jakub Jankowski
  2019-07-11 12:08         ` Florian Westphal
  0 siblings, 1 reply; 6+ messages in thread
From: Jakub Jankowski @ 2019-07-11  9:36 UTC (permalink / raw)
  To: Jozsef Kadlecsik; +Cc: netfilter, mhemsley, netfilter-devel

On 2019-07-11, Jozsef Kadlecsik wrote:

> Hi,
>
> On Wed, 10 Jul 2019, Jakub Jankowski wrote:
>
>> On 2019-07-10, Jozsef Kadlecsik wrote:
>>
>>> On Wed, 10 Jul 2019, Jakub Jankowski wrote:
>>>
>>>> We're debugging a weird issue. tl;dr: I have a .pcap file of connection
>>>> setup that makes conntrack apply TCP_CONNTRACK_RETRANS timeout (300s by
>>>> default) instead of TCP_CONNTRACK_ESTABLISHED (5d by default). The .pcap
>>>> is a recording of some app traffic running on Windows (SAP, I believe).
>>>>
>>>> The offending handshake is:
>>>>
>>>> root@testhost0:~# tcpdump -v -nn --absolute-tcp-sequence-numbers -r
>>>> replayed-traffic.pcap
>>>> reading from file replayed-traffic.pcap, link-type EN10MB (Ethernet)
>>>> 01:13:25.070622 IP (tos 0x0, ttl 128, id 35410, offset 0, flags [DF],
>>>> proto
>>>> TCP (6), length 52)
>>>>     10.88.15.142.51451 > 10.88.1.2.3230: Flags [S], cksum 0x1473
>>>> (correct),
>>>> seq 962079611, win 64240, options [mss 1460,nop,wscale 8,nop,nop,sackOK],
>>>> length 0
>>>> 01:13:26.070462 IP (tos 0x0, ttl 53, id 29815, offset 0, flags [DF], proto
>>>> TCP
>>>> (6), length 48)
>>>>     10.88.1.2.3230 > 10.88.15.142.51451: Flags [S.], cksum 0x70cf
>>>> (correct),
>>>> seq 1148284782, ack 962079612, win 65535, options [mss 1380,nop,wscale 3],
>>>> length 0
>>>> 01:13:27.070449 IP (tos 0x0, ttl 128, id 35411, offset 0, flags [DF],
>>>> proto
>>>> TCP (6), length 40)
>>>>     10.88.15.142.51451 > 10.88.1.2.3230: Flags [.], cksum 0x9a46
>>>> (correct),
>>>> ack 1148284783, win 512, length 0
>>>>
>>>> This conversation results in the following conntrack events:
>>>>
>>>> root@testhost0:~# conntrack -E --orig-src 10.88.15.142
>>>>     [NEW] tcp      6 120 SYN_SENT src=10.88.15.142 dst=10.88.1.2
>>>> sport=51451
>>>> dport=3230 [UNREPLIED] src=10.88.1.2 dst=10.88.15.142 sport=3230
>>>> dport=51451
>>>>  [UPDATE] tcp      6 60 SYN_RECV src=10.88.15.142 dst=10.88.1.2
>>>> sport=51451
>>>> dport=3230 src=10.88.1.2 dst=10.88.15.142 sport=3230 dport=51451
>>>>  [UPDATE] tcp      6 312 ESTABLISHED src=10.88.15.142 dst=10.88.1.2
>>>> sport=51451 dport=3230 src=10.88.1.2 dst=10.88.15.142 sport=3230
>>>> dport=51451
>>>> [ASSURED]
>>>>
>>>>
>>>> After enabling all pr_debug()s in nf_conntrack_proto_tcp.c, the above
>>>> handshake results in this:
>>>
>>> Thanks for the thorough report, but the kernel debug log above does not
>>> correspond to the packet replay: the TCP parameters do not match. Please
>>> send the proper debug log, so we can look into it.
>>
>> Argh. My bad, wrong copy&paste, sorry. Here goes the correct debug snippet:
>
> The kernel does not print enough information. Could you apply the attached
> patch to your kernel at the test machine, rerun the test and send the
> logs?

Thanks for looking into this. 4.19.57 with your patch:

- "bad" case:

Jul 11 11:22:39 testhost0 kernel: [   45.360287] tcp_new: sender 
end=962079612 maxend=962079612 maxwin=64240 scale=8 receiver end=0 
maxend=0 maxwin=0 scale=0
Jul 11 11:22:39 testhost0 kernel: [   45.360322] tcp_in_window: START
Jul 11 11:22:39 testhost0 kernel: [   45.360330] tcp_in_window:
Jul 11 11:22:39 testhost0 kernel: [   45.360342] seq=962079611 ack=0+(0) 
sack=0+(0) win=64240 end=962079612
Jul 11 11:22:39 testhost0 kernel: [   45.360354] tcp_in_window: sender 
end=962079612 maxend=962079612 maxwin=64240 scale=8 receiver end=0 
maxend=0 maxwin=0 scale=0 last dir=0 seq=0 ack=0 end=0 win=0 retrans=0
Jul 11 11:22:39 testhost0 kernel: [   45.360361] tcp_in_window:
Jul 11 11:22:39 testhost0 kernel: [   45.360371] seq=962079611 ack=0+(0) 
sack=0+(0) win=64240 end=962079612
Jul 11 11:22:39 testhost0 kernel: [   45.360381] tcp_in_window: sender 
end=962079612 maxend=962079612 maxwin=64240 scale=8 receiver end=0 
maxend=0 maxwin=0 scale=0
Jul 11 11:22:39 testhost0 kernel: [   45.360390] tcp_in_window: I=1 II=1 
III=1 IV=1
Jul 11 11:22:39 testhost0 kernel: [   45.360402] tcp_in_window: res=1 
sender end=962079612 maxend=962079612 maxwin=64240 scale=8 receiver end=0 
maxend=64240 maxwin=0 scale=0 last dir=0 seq=0 ack=0 end=0 win=0 retrans=0
Jul 11 11:22:39 testhost0 kernel: [   45.360410] tcp_conntracks:
Jul 11 11:22:39 testhost0 kernel: [   45.360419] syn=1 ack=0 fin=0 rst=0 
old=0 new=1
Jul 11 11:22:40 testhost0 kernel: [   46.359998] tcp_in_window: START
Jul 11 11:22:40 testhost0 kernel: [   46.360009] tcp_in_window:
Jul 11 11:22:40 testhost0 kernel: [   46.360012] seq=1148284782 
ack=962079612+(0) sack=962079612+(0) win=65535 end=1148284783
Jul 11 11:22:40 testhost0 kernel: [   46.360015] tcp_in_window: sender 
end=0 maxend=64240 maxwin=0 scale=0 receiver end=962079612 
maxend=962079612 maxwin=64240 scale=8 last dir=0 seq=0 ack=0 end=0 win=0 
retrans=0
Jul 11 11:22:40 testhost0 kernel: [   46.360017] tcp_in_window:
Jul 11 11:22:40 testhost0 kernel: [   46.360019] seq=1148284782 
ack=962079612+(0) sack=962079612+(0) win=65535 end=1148284783
Jul 11 11:22:40 testhost0 kernel: [   46.360021] tcp_in_window: sender 
end=1148284783 maxend=1148284783 maxwin=65535 scale=3 receiver 
end=962079612 maxend=962079612 maxwin=64240 scale=8
Jul 11 11:22:40 testhost0 kernel: [   46.360022] tcp_in_window: I=1 II=1 
III=1 IV=1
Jul 11 11:22:40 testhost0 kernel: [   46.360025] tcp_in_window: res=1 
sender end=1148284783 maxend=1148284783 maxwin=65535 scale=3 receiver 
end=962079612 maxend=962145147 maxwin=64240 scale=8 last dir=0 seq=0 ack=0 
end=0 win=0 retrans=0
Jul 11 11:22:40 testhost0 kernel: [   46.360026] tcp_conntracks:
Jul 11 11:22:40 testhost0 kernel: [   46.360028] syn=1 ack=1 fin=0 rst=0 
old=1 new=2
Jul 11 11:22:41 testhost0 kernel: [   47.359983] tcp_in_window: START
Jul 11 11:22:41 testhost0 kernel: [   47.359991] tcp_in_window:
Jul 11 11:22:41 testhost0 kernel: [   47.359994] seq=962079612 
ack=1148284783+(0) sack=1148284783+(0) win=512 end=962079612
Jul 11 11:22:41 testhost0 kernel: [   47.359997] tcp_in_window: sender 
end=962079612 maxend=962145147 maxwin=64240 scale=8 receiver 
end=1148284783 maxend=1148284783 maxwin=65535 scale=3 last dir=1 seq=0 
ack=0 end=0 win=0 retrans=0
Jul 11 11:22:41 testhost0 kernel: [   47.359998] tcp_in_window:
Jul 11 11:22:41 testhost0 kernel: [   47.360003] seq=962079612 
ack=1148284783+(0) sack=1148284783+(0) win=512 end=962079612
Jul 11 11:22:41 testhost0 kernel: [   47.360005] tcp_in_window: sender 
end=962079612 maxend=962145147 maxwin=64240 scale=8 receiver 
end=1148284783 maxend=1148284783 maxwin=65535 scale=3
Jul 11 11:22:41 testhost0 kernel: [   47.360006] tcp_in_window: I=1 II=1 
III=1 IV=1
Jul 11 11:22:41 testhost0 kernel: [   47.360009] tcp_in_window: res=1 
sender end=962079612 maxend=962145147 maxwin=131072 scale=8 receiver 
end=1148284783 maxend=1148415855 maxwin=65535 scale=3 last dir=0 
seq=962079612 ack=1148284783 end=962079612 win=0 retrans=0
Jul 11 11:22:41 testhost0 kernel: [   47.360010] tcp_conntracks:
Jul 11 11:22:41 testhost0 kernel: [   47.360012] syn=0 ack=1 fin=0 rst=0 
old=2 new=3


- "normal" case (regular telnet between two linux hosts)

# grep 'Jul 11 11:25:' /var/log/kern.log
Jul 11 11:25:24 testhost0 kernel: [  211.343481] tcp_new: sender 
end=985051953 maxend=985051953 maxwin=29200 scale=7 receiver end=0 
maxend=0 maxwin=0 scale=0
Jul 11 11:25:24 testhost0 kernel: [  211.343522] tcp_in_window: START
Jul 11 11:25:24 testhost0 kernel: [  211.343524] tcp_in_window:
Jul 11 11:25:24 testhost0 kernel: [  211.343526] seq=985051952 ack=0+(0) 
sack=0+(0) win=29200 end=985051953
Jul 11 11:25:24 testhost0 kernel: [  211.343528] tcp_in_window: sender 
end=985051953 maxend=985051953 maxwin=29200 scale=7 receiver end=0 
maxend=0 maxwin=0 scale=0 last dir=0 seq=0 ack=0 end=0 win=0 retrans=0
Jul 11 11:25:24 testhost0 kernel: [  211.343530] tcp_in_window:
Jul 11 11:25:24 testhost0 kernel: [  211.343532] seq=985051952 ack=0+(0) 
sack=0+(0) win=29200 end=985051953
Jul 11 11:25:24 testhost0 kernel: [  211.343534] tcp_in_window: sender 
end=985051953 maxend=985051953 maxwin=29200 scale=7 receiver end=0 
maxend=0 maxwin=0 scale=0
Jul 11 11:25:24 testhost0 kernel: [  211.343538] tcp_in_window: I=1 II=1 
III=1 IV=1
Jul 11 11:25:24 testhost0 kernel: [  211.343541] tcp_in_window: res=1 
sender end=985051953 maxend=985051953 maxwin=29200 scale=7 receiver end=0 
maxend=29200 maxwin=0 scale=0 last dir=0 seq=0 ack=0 end=0 win=0 retrans=0
Jul 11 11:25:24 testhost0 kernel: [  211.343542] tcp_conntracks:
Jul 11 11:25:24 testhost0 kernel: [  211.343544] syn=1 ack=0 fin=0 rst=0 
old=0 new=1
Jul 11 11:25:24 testhost0 kernel: [  211.344034] tcp_in_window: START
Jul 11 11:25:24 testhost0 kernel: [  211.344040] tcp_in_window:
Jul 11 11:25:24 testhost0 kernel: [  211.344042] seq=1537183414 
ack=985051953+(0) sack=985051953+(0) win=28960 end=1537183415
Jul 11 11:25:24 testhost0 kernel: [  211.344044] tcp_in_window: sender 
end=0 maxend=29200 maxwin=0 scale=0 receiver end=985051953 
maxend=985051953 maxwin=29200 scale=7 last dir=0 seq=0 ack=0 end=0 win=0 
retrans=0
Jul 11 11:25:24 testhost0 kernel: [  211.344046] tcp_in_window:
Jul 11 11:25:24 testhost0 kernel: [  211.344048] seq=1537183414 
ack=985051953+(0) sack=985051953+(0) win=28960 end=1537183415
Jul 11 11:25:24 testhost0 kernel: [  211.344050] tcp_in_window: sender 
end=1537183415 maxend=1537183415 maxwin=28960 scale=7 receiver 
end=985051953 maxend=985051953 maxwin=29200 scale=7
Jul 11 11:25:24 testhost0 kernel: [  211.344051] tcp_in_window: I=1 II=1 
III=1 IV=1
Jul 11 11:25:24 testhost0 kernel: [  211.344054] tcp_in_window: res=1 
sender end=1537183415 maxend=1537183415 maxwin=28960 scale=7 receiver 
end=985051953 maxend=985080913 maxwin=29200 scale=7 last dir=0 seq=0 ack=0 
end=0 win=0 retrans=0
Jul 11 11:25:24 testhost0 kernel: [  211.344055] tcp_conntracks:
Jul 11 11:25:24 testhost0 kernel: [  211.344057] syn=1 ack=1 fin=0 rst=0 
old=1 new=2
Jul 11 11:25:24 testhost0 kernel: [  211.344888] tcp_in_window: START
Jul 11 11:25:24 testhost0 kernel: [  211.344888] tcp_in_window:
Jul 11 11:25:24 testhost0 kernel: [  211.344889] seq=985051953 
ack=1537183415+(0) sack=1537183415+(0) win=229 end=985051953
Jul 11 11:25:24 testhost0 kernel: [  211.344891] tcp_in_window: sender 
end=985051953 maxend=985080913 maxwin=29200 scale=7 receiver 
end=1537183415 maxend=1537183415 maxwin=28960 scale=7 last dir=1 seq=0 
ack=0 end=0 win=0 retrans=0
Jul 11 11:25:24 testhost0 kernel: [  211.344891] tcp_in_window:
Jul 11 11:25:24 testhost0 kernel: [  211.344892] seq=985051953 
ack=1537183415+(0) sack=1537183415+(0) win=229 end=985051953
Jul 11 11:25:24 testhost0 kernel: [  211.344892] tcp_in_window: sender 
end=985051953 maxend=985080913 maxwin=29200 scale=7 receiver 
end=1537183415 maxend=1537183415 maxwin=28960 scale=7
Jul 11 11:25:24 testhost0 kernel: [  211.344893] tcp_in_window: I=1 II=1 
III=1 IV=1
Jul 11 11:25:24 testhost0 kernel: [  211.344894] tcp_in_window: res=1 
sender end=985051953 maxend=985080913 maxwin=29312 scale=7 receiver 
end=1537183415 maxend=1537212727 maxwin=28960 scale=7 last dir=0 
seq=985051953 ack=1537183415 end=985051953 win=29312 retrans=0
Jul 11 11:25:24 testhost0 kernel: [  211.344894] tcp_conntracks:
Jul 11 11:25:24 testhost0 kernel: [  211.344895] syn=0 ack=1 fin=0 rst=0 
old=2 new=3


Looks like the only relevant difference between these two is that in "bad" 
case state->last_win stays 0.


Regards,
  Jakub.

-- 
Jakub Jankowski|shasta@toxcorp.com|https://toxcorp.com/

^ permalink raw reply	[flat|nested] 6+ messages in thread
* Re: 3-way handshake sets conntrack timeout to max_retrans
  2019-07-11  9:36       ` Jakub Jankowski
@ 2019-07-11 12:08         ` Florian Westphal
  2019-07-11 12:52           ` Jakub Jankowski
  0 siblings, 1 reply; 6+ messages in thread
From: Florian Westphal @ 2019-07-11 12:08 UTC (permalink / raw)
  To: Jakub Jankowski; +Cc: Jozsef Kadlecsik, netfilter, mhemsley, netfilter-devel

Jakub Jankowski <shasta@toxcorp.com> wrote:

Thanks for the detailed bug report!

Can you try this fix?

diff --git a/net/netfilter/nf_conntrack_proto_tcp.c b/net/netfilter/nf_conntrack_proto_tcp.c
--- a/net/netfilter/nf_conntrack_proto_tcp.c
+++ b/net/netfilter/nf_conntrack_proto_tcp.c
@@ -472,6 +472,7 @@ static bool tcp_in_window(const struct nf_conn *ct,
 	struct ip_ct_tcp_state *receiver = &state->seen[!dir];
 	const struct nf_conntrack_tuple *tuple = &ct->tuplehash[dir].tuple;
 	__u32 seq, ack, sack, end, win, swin;
+	u16 win_raw;
 	s32 receiver_offset;
 	bool res, in_recv_win;
 
@@ -480,7 +481,8 @@ static bool tcp_in_window(const struct nf_conn *ct,
 	 */
 	seq = ntohl(tcph->seq);
 	ack = sack = ntohl(tcph->ack_seq);
-	win = ntohs(tcph->window);
+	win_raw = ntohs(tcph->window);
+	win = win_raw;
 	end = segment_seq_plus_len(seq, skb->len, dataoff, tcph);
 
 	if (receiver->flags & IP_CT_TCP_FLAG_SACK_PERM)
@@ -655,14 +657,14 @@ static bool tcp_in_window(const struct nf_conn *ct,
 			    && state->last_seq == seq
 			    && state->last_ack == ack
 			    && state->last_end == end
-			    && state->last_win == win)
+			    && state->last_win == win_raw)
 				state->retrans++;
 			else {
 				state->last_dir = dir;
 				state->last_seq = seq;
 				state->last_ack = ack;
 				state->last_end = end;
-				state->last_win = win;
+				state->last_win = win_raw;
 				state->retrans = 0;
 			}
 		}

^ permalink raw reply	[flat|nested] 6+ messages in thread
* Re: 3-way handshake sets conntrack timeout to max_retrans
  2019-07-11 12:08         ` Florian Westphal
@ 2019-07-11 12:52           ` Jakub Jankowski
  0 siblings, 0 replies; 6+ messages in thread
From: Jakub Jankowski @ 2019-07-11 12:52 UTC (permalink / raw)
  To: Florian Westphal; +Cc: Jozsef Kadlecsik, netfilter, mhemsley, netfilter-devel

On 2019-07-11, Florian Westphal wrote:

> Can you try this fix?
>
> diff --git a/net/netfilter/nf_conntrack_proto_tcp.c b/net/netfilter/nf_conntrack_proto_tcp.c
> --- a/net/netfilter/nf_conntrack_proto_tcp.c
> +++ b/net/netfilter/nf_conntrack_proto_tcp.c
> @@ -472,6 +472,7 @@ static bool tcp_in_window(const struct nf_conn *ct,
> 	struct ip_ct_tcp_state *receiver = &state->seen[!dir];
> 	const struct nf_conntrack_tuple *tuple = &ct->tuplehash[dir].tuple;
> 	__u32 seq, ack, sack, end, win, swin;
> +	u16 win_raw;
> 	s32 receiver_offset;
> 	bool res, in_recv_win;
>
> @@ -480,7 +481,8 @@ static bool tcp_in_window(const struct nf_conn *ct,
> 	 */
> 	seq = ntohl(tcph->seq);
> 	ack = sack = ntohl(tcph->ack_seq);
> -	win = ntohs(tcph->window);
> +	win_raw = ntohs(tcph->window);
> +	win = win_raw;
> 	end = segment_seq_plus_len(seq, skb->len, dataoff, tcph);
>
> 	if (receiver->flags & IP_CT_TCP_FLAG_SACK_PERM)
> @@ -655,14 +657,14 @@ static bool tcp_in_window(const struct nf_conn *ct,
> 			    && state->last_seq == seq
> 			    && state->last_ack == ack
> 			    && state->last_end == end
> -			    && state->last_win == win)
> +			    && state->last_win == win_raw)
> 				state->retrans++;
> 			else {
> 				state->last_dir = dir;
> 				state->last_seq = seq;
> 				state->last_ack = ack;
> 				state->last_end = end;
> -				state->last_win = win;
> +				state->last_win = win_raw;
> 				state->retrans = 0;
> 			}
> 		}

Thanks for the quick turnaround, Florian!

I can confirm this indeed fixes my test case, I now get the expected
  [UPDATE] tcp      6 432000 ESTABLISHED src=10.88.15.142 dst=10.88.1.2 
sport=51451 dport=3230 src=10.88.1.2 dst=10.88.15.142 sport=3230 
dport=51451 [ASSURED]

If that's going to be the official fix, feel free to add
Tested-By: Jakub Jankowski <shasta@toxcorp.com>


Regards,
  Jakub.


-- 
Jakub Jankowski|shasta@toxcorp.com|https://toxcorp.com/

^ permalink raw reply	[flat|nested] 6+ messages in thread
end of thread, other threads:[~2019-07-11 12:52 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
     [not found] <alpine.LNX.2.21.1907100147540.26040@kich.toxcorp.com>
2019-07-10 10:46 ` 3-way handshake sets conntrack timeout to max_retrans Jozsef Kadlecsik
2019-07-10 10:54   ` Jakub Jankowski
2019-07-11  9:01     ` Jozsef Kadlecsik
2019-07-11  9:36       ` Jakub Jankowski
2019-07-11 12:08         ` Florian Westphal
2019-07-11 12:52           ` Jakub Jankowski

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.