From owner-freebsd-ipfw@FreeBSD.ORG Thu Feb 19 20:17:06 2004 Return-Path: Delivered-To: freebsd-ipfw@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 60D3716A4CE; Thu, 19 Feb 2004 20:17:06 -0800 (PST) Received: from new.iagu.net (new.iagu.net [203.32.153.76]) by mx1.FreeBSD.org (Postfix) with ESMTP id 7E54F43D1D; Thu, 19 Feb 2004 20:17:05 -0800 (PST) (envelope-from andrewr-freebsd@iagu.net) Received: from [10.10.11.197] (pop@ns.iagu.net [203.32.153.69]) by new.iagu.net (8.12.9/8.12.4) with ESMTP id i1K4H0jl075292; Fri, 20 Feb 2004 14:47:02 +1030 (CST) (envelope-from andrewr-freebsd@iagu.net) Mime-Version: 1.0 X-Sender: andrewr+freebsd@127.0.0.1 Message-Id: Date: Fri, 20 Feb 2004 14:46:55 +1030 To: freebsd-ipfw@freebsd.org From: Andrew Rutherford Content-Type: text/plain; charset="us-ascii" ; format="flowed" cc: Greg 'groggy' Lehey Subject: Long processing delays in NAT in 5.2.1-RC X-BeenThere: freebsd-ipfw@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: IPFW Technical Discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 20 Feb 2004 04:17:06 -0000 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 (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 (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 (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 (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 (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 (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 (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 (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 (DF) 20:05:25.502612 217.77.6.116.48159 > 203.38.229.157.2506: P 25:51(26) ack 1 win 63603 (DF) 20:05:25.694392 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51) ack 1 win 63603 (DF) 20:05:27.055264 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51) ack 1 win 63603 (DF) 20:05:29.780017 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51) ack 1 win 63603 (DF) 20:05:34.980158 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51) ack 1 win 63603 (DF) 20:05:45.702070 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51) ack 1 win 63603 (DF) 20:06:07.140772 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51) ack 1 win 63603 (DF) 20:06:50.023919 217.77.6.116.48159 > 203.38.229.157.2506: P 0:51(51) ack 1 win 63603 (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 (DF) 20:07:41.493573 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26) ack 0 win 15364 (DF) 20:07:41.493656 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26) ack 0 win 15364 (DF) 20:07:41.493746 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26) ack 0 win 15364 (DF) 20:07:41.493829 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26) ack 0 win 15364 (DF) 20:07:41.493920 203.38.229.157.2506 > 217.77.6.116.48159: P 1:27(26) ack 0 win 15364 (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 (DF) 20:07:41.861585 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27 win 63603 (DF) 20:07:41.862024 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27 win 63603 (DF) 20:07:41.862759 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27 win 63603 (DF) 20:07:41.863342 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27 win 63603 (DF) 20:07:41.863929 217.77.6.116.48159 > 203.38.229.157.2506: . ack 27 win 63603 (DF) 20:07:41.887626 217.77.6.116.48159 > 203.38.229.157.2506: FP 51:101(50) ack 27 win 63603 (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