Transfer stalls with NAT under 2.6.24.3

Transfer stalls with NAT under 2.6.24.3

[Sven Riedel]

Hi,
I've run into a strange problem where large file transfers start 
stalling over a NATed connection. Packet traces reveal that ACK packets 
are sometimes not being passed through to the inside (NATed) host, which 
results in a transfer stall until a tcp timeout occurrs and the other 
side retransmits the ACK.

This only seems to happen if the conntrack table on the firewall already 
contains an entry for the same source and destination in TIME_WAIT 
state. If no conntrack entries exist for the same source and 
destination, the packets flow fine.

The problem seems to be alevated by setting ip_conntrac_tcp_be_liberal 
to 1, but this seems to be only a workaround not a real solution.

Scatter gather and tcp segment offloading have been disabled in the 
relevant NICs on the firewall during debugging, to make sure this isn't 
a hardware issue.

Is this issue known/is there a patch available or would further 
information be needed to help debug the problem?

Regards,
Sven

-- 
sven.riedel@securenet.de

SecureNet GmbH
Intranet & Internet Solutions
Frankfurter Ring 193a
D-80807 München
Tel: +49 89 32133-632
Fax: +49 89 32133-699
Zentrale: -600
www.securenet.de

Sitz der Gesellschaft: München
HRB München 118876
Geschäftsführer: Thomas Schreiber

Re: Transfer stalls with NAT under 2.6.24.3

[Patrick McHardy]

Sven Riedel wrote:
> Hi,
> I've run into a strange problem where large file transfers start 
> stalling over a NATed connection. Packet traces reveal that ACK 
> packets are sometimes not being passed through to the inside (NATed) 
> host, which results in a transfer stall until a tcp timeout occurrs 
> and the other side retransmits the ACK.
>
> This only seems to happen if the conntrack table on the firewall 
> already contains an entry for the same source and destination in 
> TIME_WAIT state. If no conntrack entries exist for the same source and 
> destination, the packets flow fine.
>
> The problem seems to be alevated by setting ip_conntrac_tcp_be_liberal 
> to 1, but this seems to be only a workaround not a real solution.
>
> Scatter gather and tcp segment offloading have been disabled in the 
> relevant NICs on the firewall during debugging, to make sure this 
> isn't a hardware issue.
>
> Is this issue known/is there a patch available or would further 
> information be needed to help debug the problem?

2.6.24.3 includes a patches that was supposed to fix problems
with connections in TIME_WAIT state. Does 2.6.24.2 work better
for you?

Please enable conntrack logging for TCP by executing:

echo 6 >/proc/sys/net/netfilter/nf_conntrack_log_invalid

and check whether you get any messages in the ring buffer.

Re: Transfer stalls with NAT under 2.6.24.3

[Sven Riedel]

Patrick McHardy wrote:
> Sven Riedel wrote:
>> Hi,
>> I've run into a strange problem where large file transfers start 
>> stalling over a NATed connection. Packet traces reveal that ACK 
>> packets are sometimes not being passed through to the inside (NATed) 
>> host, which results in a transfer stall until a tcp timeout occurrs 
>> and the other side retransmits the ACK.
>>
>> This only seems to happen if the conntrack table on the firewall 
>> already contains an entry for the same source and destination in 
>> TIME_WAIT state. If no conntrack entries exist for the same source and 
>> destination, the packets flow fine.
>>
>> The problem seems to be alevated by setting ip_conntrac_tcp_be_liberal 
>> to 1, but this seems to be only a workaround not a real solution.
>>
>> Scatter gather and tcp segment offloading have been disabled in the 
>> relevant NICs on the firewall during debugging, to make sure this 
>> isn't a hardware issue.
>>
>> Is this issue known/is there a patch available or would further 
>> information be needed to help debug the problem?
> 
> 2.6.24.3 includes a patches that was supposed to fix problems
> with connections in TIME_WAIT state. Does 2.6.24.2 work better
> for you?

The firewall system in question is currently productive. I _might_ be 
able to try the other kernel tomorrow morning. Once I am able to try it 
I'll let you know.

> 
> Please enable conntrack logging for TCP by executing:
> 
> echo 6 >/proc/sys/net/netfilter/nf_conntrack_log_invalid
> 
> and check whether you get any messages in the ring buffer.

Yep, lots ;)

In the following 100.100.100.100 is the external machine and 
200.200.200.200 is the NAT IP-Address on the firewall. A 5MB file was 
transferred via scp to 100.100.100.100 from the internal network.

The output during a "clean" run, with an empty conntrack table and no 
stalls:
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=42121
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355720612 ACK=3828427355 WINDOW=47880
RES=0x00 ACK URGP=0 OPT (0101080A45585E351B138AA40101050AE50974FBE5097A53)
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=42122
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355720612 ACK=3828427355 WINDOW=47880
RES=0x00 ACK URGP=0 OPT (0101080A45585E361B138AA40101050AE50974FBE5097FAB)
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=42123
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355720612 ACK=3828427355 WINDOW=47880
RES=0x00 ACK URGP=0 OPT (0101080A45585E361B138AA40101050AE50974FBE5098503)
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=42124
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355720612 ACK=3828427355 WINDOW=47880
RES=0x00 ACK URGP=0 OPT (0101080A45585E371B138AA40101050AE50974FBE5098A5B)
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=42125
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355720612 ACK=3828427355 WINDOW=47880
RES=0x00 ACK URGP=0 OPT (0101080A45585E381B138AA40101050AE50974FBE5098FB3)
printk: 24 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=42248
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355720852 ACK=3828837755 WINDOW=49248
RES=0x00 ACK URGP=0 OPT (0101080A45585F911B138E140101050AE50FB2C3E50FD2D3)
printk: 31 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=42465
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355721284 ACK=3829614779 WINDOW=49248
RES=0x00 ACK URGP=0 OPT (0101080A455861861B1392E10101050AE51B935BE51BB8C3)
printk: 25 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=42718
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355721716 ACK=3830353499 WINDOW=42408
RES=0x00 ACK URGP=0 OPT (0101080A455863DA1B1398B70101050AE526E3ABE526E903)
printk: 57 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=42976
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355722052 ACK=3830954051 WINDOW=49248
RES=0x00 ACK URGP=0 OPT (0101080A455865791B139CBE0101050AE52FFD8BE530284B)
printk: 27 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=72 TOS=0x00 PREC=0x00 TTL=56 
ID=43306
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355722580 ACK=3831787163 WINDOW=42408
RES=0x00 ACK URGP=0 OPT
(0101080A455867731B13A19501010512E53CCB53E53CD653E53CBE93E53CC3EB)
printk: 74 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=43789
DF PROTO=TCP SPT=22 DPT=43021 SEQ=355723252 ACK=3832978011 WINDOW=42408
RES=0x00 ACK URGP=0 OPT (0101080A45586A571B13A8CF0101050AE54EDEABE54EE403)







During a run with stalls:

nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=80 TOS=0x00 PREC=0x00 TTL=56 
ID=44105
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160349927 ACK=596614326 WINDOW=49248
RES=0x00 ACK URGP=0 OPT
(0101080A4558793C1B13CE350101051A491E8751491E8CA9491E7B71491E81F9491E40A9491E5B61)

^^^^ Transfer stalled here for ~10 seconds.


printk: 22 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=72 TOS=0x00 PREC=0x00 TTL=56 
ID=44113
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160349927 ACK=596632110 WINDOW=49248
RES=0x00 ACK URGP=0 OPT
(0101080A45587D301B13D81801010512491E8751491E8CA9491E7B71491E81F9)
printk: 12 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=44114
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160349927 ACK=596635150 WINDOW=49248
RES=0x00 ACK URGP=0 OPT (0101080A455881B21B13E35A0101050A491E8751491E8CA9)
printk: 14 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=7320
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160350311 ACK=597280038 WINDOW=27360
RES=0x00 ACK URGP=0 OPT (0101080A455883D31B13E8820101050A49286E71492873C9)
printk: 32 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=7451
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160350503 ACK=597578342 WINDOW=49248
RES=0x00 ACK URGP=0 OPT (0101080A455885161B13EBD30101050A492CEBA9492CF659)
printk: 35 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=7786
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160350983 ACK=598415558 WINDOW=49248
RES=0x00 ACK URGP=0 OPT (0101080A455887081B13F0890101050A4939B2094939E221)
printk: 54 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=8021
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160351319 ACK=598980542 WINDOW=42408
RES=0x00 ACK URGP=0 OPT (0101080A455889151B13F5C00101050A4942510149425659)
printk: 43 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=8205
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160351559 ACK=599403254 WINDOW=49248
RES=0x00 ACK URGP=0 OPT (0101080A45588B011B13FA9B0101050A4948C4394948C991)
printk: 40 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=8531
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160352039 ACK=600218582 WINDOW=45144
RES=0x00 ACK URGP=0 OPT (0101080A45588D371B1400160101050A4955351949553A71)
printk: 49 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=8871
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160352519 ACK=601058534 WINDOW=38304
RES=0x00 ACK URGP=0 OPT (0101080A45588F521B1405500101050A4962062949620B81)
printk: 45 messages suppressed.
nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
ID=8988
DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160352663 ACK=601307510 WINDOW=41040
RES=0x00 ACK URGP=0 OPT (0101080A4558910A1B1409AB0101050A4965D2B94965D811)


Regards,
Sven
-- 
sven.riedel@securenet.de

SecureNet GmbH
Intranet & Internet Solutions
Frankfurter Ring 193a
D-80807 München
Tel: +49 89 32133-632
Fax: +49 89 32133-699
Zentrale: -600
www.securenet.de

Sitz der Gesellschaft: München
HRB München 118876
Geschäftsführer: Thomas Schreiber

Re: Transfer stalls with NAT under 2.6.24.3

[Patrick McHardy]

Sven Riedel wrote:
> Patrick McHardy wrote:
>> Sven Riedel wrote:
>>> Is this issue known/is there a patch available or would further 
>>> information be needed to help debug the problem?
>>
>> 2.6.24.3 includes a patches that was supposed to fix problems
>> with connections in TIME_WAIT state. Does 2.6.24.2 work better
>> for you?
> 
> The firewall system in question is currently productive. I _might_ be 
> able to try the other kernel tomorrow morning. Once I am able to try it 
> I'll let you know.
> 
>>
>> Please enable conntrack logging for TCP by executing:
>>
>> echo 6 >/proc/sys/net/netfilter/nf_conntrack_log_invalid
>>
>> and check whether you get any messages in the ring buffer.
> 
> Yep, lots ;)
> 
> In the following 100.100.100.100 is the external machine and 
> 200.200.200.200 is the NAT IP-Address on the firewall. A 5MB file was 
> transferred via scp to 100.100.100.100 from the internal network.
> 
> The output during a "clean" run, with an empty conntrack table and no 
> stalls:
> nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
> SRC=100.100.100.100 DST=200.200.200.200 LEN=64 TOS=0x00 PREC=0x00 TTL=56 
> ID=42121
> ...
> 
> During a run with stalls:
> 
> nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
> SRC=100.100.100.100 DST=200.200.200.200 LEN=80 TOS=0x00 PREC=0x00 TTL=56 
> ID=44105
> DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160349927 ACK=596614326 WINDOW=49248
> RES=0x00 ACK URGP=0 OPT
> (0101080A4558793C1B13CE350101051A491E8751491E8CA9491E7B71491E81F9491E40A9491E5B61) 
> 
> 
> ^^^^ Transfer stalled here for ~10 seconds.
> 
> 
> printk: 22 messages suppressed.
> nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
> SRC=100.100.100.100 DST=200.200.200.200 LEN=72 TOS=0x00 PREC=0x00 TTL=56 
> ID=44113

Thanks, can you send a binary tcpdump (... -w file) of a connection
that triggers these messages please?

Re: Transfer stalls with NAT under 2.6.24.3

[Jozsef Kadlecsik]

On Wed, 26 Mar 2008, Patrick McHardy wrote:

> > During a run with stalls:
> > 
> > nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
> > SRC=100.100.100.100 DST=200.200.200.200 LEN=80 TOS=0x00 PREC=0x00 TTL=56
> > ID=44105
> > DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160349927 ACK=596614326 WINDOW=49248
> > RES=0x00 ACK URGP=0 OPT
> > (0101080A4558793C1B13CE350101051A491E8751491E8CA9491E7B71491E81F9491E40A9491E5B61) 
> > 
> Thanks, can you send a binary tcpdump (... -w file) of a connection
> that triggers these messages please?

Yes, a tcpdump of a full session which is stalled could help a lot.

But it almost look like as a SACK related problem: isn't there a (new) 
device between the communicating parties which performs ISN randomization 
and fails to adjust SACK?

Best regards,
Jozsef
-
E-mail  : kadlec@blackhole.kfki.hu, kadlec@sunserv.kfki.hu
PGP key : http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address : KFKI Research Institute for Particle and Nuclear Physics
          H-1525 Budapest 114, POB. 49, Hungary

Re: Transfer stalls with NAT under 2.6.24.3

[Krzysztof Oledzki]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 1303 bytes --]



On Wed, 26 Mar 2008, Jozsef Kadlecsik wrote:

> On Wed, 26 Mar 2008, Patrick McHardy wrote:
>
>>> During a run with stalls:
>>>
>>> nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
>>> SRC=100.100.100.100 DST=200.200.200.200 LEN=80 TOS=0x00 PREC=0x00 TTL=56
>>> ID=44105
>>> DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160349927 ACK=596614326 WINDOW=49248
>>> RES=0x00 ACK URGP=0 OPT
>>> (0101080A4558793C1B13CE350101051A491E8751491E8CA9491E7B71491E81F9491E40A9491E5B61)
>>>
>> Thanks, can you send a binary tcpdump (... -w file) of a connection
>> that triggers these messages please?
>
> Yes, a tcpdump of a full session which is stalled could help a lot.
>
> But it almost look like as a SACK related problem: isn't there a (new)
> device between the communicating parties which performs ISN randomization
> and fails to adjust SACK?

Yep.

$ ./optparse 0101080A4558793C1B13CE350101051A491E8751491E8CA9491E7B71491E81F9491E40A9491E5B61
No-Operation
No-Operation
TSOPT - Time Stamp Option(8) tv=1163426108 er=454282805
No-Operation
No-Operation
SACK(24) 1226737489:1226738857(1368) 1226734449:1226736121(1672) 1226719401:1226726241(6840)

So, SEQ=4160349927 & ACK=596614326 vs. 12267????? is obviously wrong.

Best regards,

 			Krzysztof Olędzki

Re: Transfer stalls with NAT under 2.6.24.3

[Sven Riedel]

Hi,
we had a minor emergency here last week, so I wasn't able to test the 
old kernel. I'll see that I'll try that tomorrow.

Jozsef Kadlecsik wrote:
> On Wed, 26 Mar 2008, Patrick McHardy wrote:
> 
>>> During a run with stalls:
>>>
>>> nf_ct_tcp: ACK is over the upper bound (ACKed data not seen yet) IN= OUT=
>>> SRC=100.100.100.100 DST=200.200.200.200 LEN=80 TOS=0x00 PREC=0x00 TTL=56
>>> ID=44105
>>> DF PROTO=TCP SPT=22 DPT=35858 SEQ=4160349927 ACK=596614326 WINDOW=49248
>>> RES=0x00 ACK URGP=0 OPT
>>> (0101080A4558793C1B13CE350101051A491E8751491E8CA9491E7B71491E81F9491E40A9491E5B61)
>>>
>> Thanks, can you send a binary tcpdump (... -w file) of a connection
>> that triggers these messages please?
> 
> Yes, a tcpdump of a full session which is stalled could help a lot.
Ok, I'll send one along later today.

> But it almost look like as a SACK related problem: isn't there a (new)
> device between the communicating parties which performs ISN randomization
> and fails to adjust SACK?

There are at least two devices between the communication partners: a DSL 
modem and a firewall on the remote end (outside of my control). Both 
devices have been there already and didn't create any problems with the 
old iptables setup. The only thing that changed on that communication 
path is the firewall hardware, the NIC on the firewall and the 
netfilter/iptables version used by the firewall.

Regards,
Sven


-- 
sven.riedel@securenet.de

SecureNet GmbH
Intranet & Internet Solutions
Frankfurter Ring 193a
D-80807 München
Tel: +49 89 32133-632
Fax: +49 89 32133-699
Zentrale: -600
www.securenet.de

Sitz der Gesellschaft: München
HRB München 118876
Geschäftsführer: Thomas Schreiber