Date: Fri, 20 Feb 2004 14:46:55 +1030 From: Andrew Rutherford <andrewr-freebsd@iagu.net> To: freebsd-ipfw@freebsd.org Cc: Greg 'groggy' Lehey <grog@freebsd.org> Subject: Long processing delays in NAT in 5.2.1-RC Message-ID: <p06010200bc5b1963bb8f@[203.32.153.125]>
next in thread | raw e-mail | index | archive | help
Summary: ipfw/natd goes into a state where packets passed to divert
sockets emerge from the system minutes (possibly hours) later.
Details:
System was recently upgraded from FreeBSD 4.6 to 5.2.1-RC, problem
not in evidence before. ipfw rules have not been changed. Things work
fine for a while, then at some point (usually when the system is
under load and the natd concerned is idle) it goes into a "slow"
state.
The system concerned has multiple natd's running, one each for a
variety of external IP addresses. One natd (or a few) can exhibit
symptoms while others are fine.
natd's affected consistently show state "DLs", natd's unaffected
usually show state "Ss". Killing and restarting the natd is not
always sufficient to clear the problem, sometimes a new process goes
straight back into "DLs" and not passing packets. In this
case,reloading the firewall rules after shutting down the natd and
before starting it again clears the problem.
I have had reports that just flushing the firewall rules is sometimes
sufficient to clear the problem without the natd being restarted, but
I haven't personally observed this myself.
natd's have occasionally (but rarely) recovered after a few hours of
no packet activity, usually around 8-9pm after everyone leaves at
5-6pm. There's a log of this happening at the bottom of the email.
Logs:
tcpdump has shown that packets seem to get "lost" and recover at some
later point in time. In the traces below, bge0 is the external
interface and fxp0 is the internal interface.
gateway# tcpdump -l -n -vvv -i bge0 net 217.77.6.0/24
tcpdump: listening on bge0
12:06:19.382097 217.77.6.116.52155 > 203.38.229.157.2506: S [tcp sum
ok] 1577731860:1577731860(0) win 5840 <mss 1380,sackOK,timestamp
618288861 0,nop,wscale 0> (DF) (ttl 44, id 63525, len 60)
12:08:25.435057 217.77.6.116.52161 > 203.38.229.157.2506: S [tcp sum
ok] 1812748282:1812748282(0) win 5840 <mss 1380,sackOK,timestamp
618301466 0,nop,wscale 0> (DF) (ttl 44, id 28017, len 60)
OK, so no packets that are part of an established session are
received on the external interface between 12:06:19 and 12:08:25.
gateway# tcpdump -l -n -vvv -i fxp0 net 217.77.6.0/24
tcpdump: listening on fxp0
12:06:16.414254 192.168.201.176.2201 > 217.77.6.116.2506: S [tcp sum
ok] 3117501023:3117501023(0) win 16384 <mss 1460,nop,nop,sackOK> (DF)
(ttl 128, id 43580, len 48)
12:06:19.403914 192.168.201.176.2201 > 217.77.6.116.2506: S [tcp sum
ok] 3117501023:3117501023(0) win 16384 <mss 1460,nop,nop,sackOK> (DF)
(ttl 128, id 43846, len 48)
12:06:25.439118 192.168.201.176.2201 > 217.77.6.116.2506: S [tcp sum
ok] 3117501023:3117501023(0) win 16384 <mss 1460,nop,nop,sackOK> (DF)
(ttl 128, id 44355, len 48)
12:07:07.511710 192.168.201.176.2220 > 217.77.6.116.2506: S [tcp sum
ok] 3131932392:3131932392(0) win 16384 <mss 1460,nop,nop,sackOK> (DF)
(ttl 128, id 48061, len 48)
12:07:10.501578 192.168.201.176.2220 > 217.77.6.116.2506: S [tcp sum
ok] 3131932392:3131932392(0) win 16384 <mss 1460,nop,nop,sackOK> (DF)
(ttl 128, id 48326, len 48)
12:07:16.536735 192.168.201.176.2220 > 217.77.6.116.2506: S [tcp sum
ok] 3131932392:3131932392(0) win 16384 <mss 1460,nop,nop,sackOK> (DF)
(ttl 128, id 48846, len 48)
12:07:39.714815 217.77.6.116.2506 > 192.168.201.176.1316: P
522389756:522389805(49) ack 1710438692 win 63612 (DF) (ttl 43, id
58082, len 89)
So suddenly the last packet has just appeared "out of nowhere",
presumably having been stored in a buffer somewhere since before the
tcpdumps were started, 83 seconds earlier. I was logged in doing some
other work during this time, the load average was 0.67 and the system
was responsive. The system was paging (MIMEdefang checking some large
emails), but not overly so.
Can anyone suggest extra debugging / tests I can do? I've run out of ideas. :-(
Thanks,
Andrew.
Other Details:
gateway# uname -a
FreeBSD gateway.elders.com.au 5.2.1-RC FreeBSD 5.2.1-RC #0: Tue Feb
17 20:19:57 CST 2004
iagu@gateway.elders.com.au:/usr/obj/usr/src/sys/FIREWALL i386
/usr/src was tossed out and reinstalled from scratch from the
5.2.1-RC ISO image.
You may have seen some comments on freebsd-current@freebsd.org about
this system with reference to stack backtraces from the filesystem -
this was fixed by turning off soft-updates on /var, but it may be
worth noting that both these problems triggered at the same time.
Recovery:
Unfortunately rare to catch this in action, here was a tcpdump on the
external interface showing packets being passed through. In this
case, the internal IP (mapped to 203.38.229.157) had been doing a
standard ping, sending packets one second apart. Around three minutes
later the natd "woke up" (this tcpdump was started well after the
ping), passed one packet, then went pack to sleep for another 40
seconds before all the queued packets in both directions were sent,
and seemed to proceed correctly from there.
(Load average was 0.05 and interactive response was good at the time.)
20:05:25.012560 217.77.6.116.48159 > 203.38.229.157.2506: P
1055660462:1055660487(25) ack 1229419771 win 63603 <nop,nop,timestamp
612523361 33800211> (DF)
20:05:25.502612 217.77.6.116.48159 > 203.38.229.157.2506: P 25:51(26)
ack 1 win 63603 <nop,nop,timestamp 612523406 33800211> (DF)
20:05:25.694392 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51)
ack 1 win 63603 <nop,nop,timestamp 612523428 33800211> (DF)
20:05:27.055264 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51)
ack 1 win 63603 <nop,nop,timestamp 612523562 33800211> (DF)
20:05:29.780017 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51)
ack 1 win 63603 <nop,nop,timestamp 612523830 33800211> (DF)
20:05:34.980158 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51)
ack 1 win 63603 <nop,nop,timestamp 612524366 33800211> (DF)
20:05:45.702070 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51)
ack 1 win 63603 <nop,nop,timestamp 612525438 33800211> (DF)
20:06:07.140772 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51)
ack 1 win 63603 <nop,nop,timestamp 612527582 33800211> (DF)
20:06:50.023919 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51)
ack 1 win 63603 <nop,nop,timestamp 612531870 33800211> (DF)
20:07:01.376276 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:01.756385 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.467390 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.472752 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473182 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473204 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473224 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473377 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473408 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473429 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473450 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473470 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473491 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473512 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473535 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473564 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473585 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473605 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473626 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473646 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.473667 203.38.229.157 > 217.77.6.116: icmp: echo request
20:07:41.475353 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26)
ack 0 win 15364 <nop,nop,timestamp 33803211 612493404> (DF)
20:07:41.493573 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26)
ack 0 win 15364 <nop,nop,timestamp 33803219 612493404> (DF)
20:07:41.493656 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26)
ack 0 win 15364 <nop,nop,timestamp 33803235 612493404> (DF)
20:07:41.493746 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26)
ack 0 win 15364 <nop,nop,timestamp 33803267 612493404> (DF)
20:07:41.493829 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26)
ack 0 win 15364 <nop,nop,timestamp 33803331 612493404> (DF)
20:07:41.493920 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26)
ack 0 win 15364 <nop,nop,timestamp 33803460 612493404> (DF)
20:07:41.531470 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419771:1229419771(0) win 0
20:07:41.531516 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419771:1229419771(0) win 0
20:07:41.531734 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419771:1229419771(0) win 0
20:07:41.531863 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419771:1229419771(0) win 0
20:07:41.531884 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419771:1229419771(0) win 0
20:07:41.532034 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419771:1229419771(0) win 0
20:07:41.532062 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419771:1229419771(0) win 0
20:07:41.532083 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419771:1229419771(0) win 0
20:07:41.532104 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419771:1229419771(0) win 0
20:07:41.835535 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.840368 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.840815 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.841684 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.842272 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.842706 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.843297 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.843883 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.844027 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.844466 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.845048 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.845488 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.846220 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.846367 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.846807 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.847393 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.847540 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.847980 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.848566 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:07:41.848713 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27
win 63603 <nop,nop,timestamp 612537053 33803211> (DF)
20:07:41.861585 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27
win 63603 <nop,nop,timestamp 612537055 33803219,nop,nop,sack sack 1
{1:27} > (DF)
20:07:41.862024 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27
win 63603 <nop,nop,timestamp 612537055 33803235,nop,nop,sack sack 1
{1:27} > (DF)
20:07:41.862759 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27
win 63603 <nop,nop,timestamp 612537055 33803267,nop,nop,sack sack 1
{1:27} > (DF)
20:07:41.863342 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27
win 63603 <nop,nop,timestamp 612537055 33803331,nop,nop,sack sack 1
{1:27} > (DF)
20:07:41.863929 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27
win 63603 <nop,nop,timestamp 612537055 33803460,nop,nop,sack sack 1
{1:27} > (DF)
20:07:41.887626 217.77.6.116.48159 > 203.38.229.157.2506: FP
51:101(50) ack 27 win 63603 <nop,nop,timestamp 612537056 33803460>
(DF)
20:07:42.076998 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419797:1229419797(0) win 0
20:07:42.077076 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419797:1229419797(0) win 0
20:07:42.077122 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419797:1229419797(0) win 0
20:07:42.077171 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419797:1229419797(0) win 0
20:07:42.077256 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419797:1229419797(0) win 0
20:07:42.077277 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419797:1229419797(0) win 0
20:07:42.077298 203.38.229.157.2506 > 217.77.6.116.48159: R
1229419797:1229419797(0) win 0
20:08:12.959301 203.38.229.157 > 217.77.6.116: icmp: echo request
20:08:13.472302 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:08:13.977312 203.38.229.157 > 217.77.6.116: icmp: echo request
20:08:14.505125 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:08:14.963946 203.38.229.157 > 217.77.6.116: icmp: echo request
20:08:15.507261 217.77.6.116 > 203.38.229.157: icmp: echo reply
20:08:15.962193 203.38.229.157 > 217.77.6.116: icmp: echo request
20:08:16.513200 217.77.6.116 > 203.38.229.157: icmp: echo reply
--
Andrew Rutherford sip:andrewr@iagu.net 244 Pirie Street
Iagu Networks tel:+61-8-8425-2255 Adelaide SA 5000
http://www.iagu.net/ mailto:andrewr@iagu.net Australia
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?p06010200bc5b1963bb8f>