pf: BAD state happens often with portsnap fetch update

Adam McDougall mcdouga9 at egr.msu.edu
Thu Oct 5 09:08:35 PDT 2006 

I have a situation where I have a number of FreeBSD 6.x servers that are
restricted from directly connecting to the internet.  To allow them to 
effectively use ports and portsnap, I have a squid http proxy that they
are allowed to use to reach the web.  This squid server is behind a 
pf bridging firewall. 

If I run portsnap fetch update on one of my servers, and if it has to download
more than 300-800 files, there is a good chance that portsnap downloading
will stall because pf decided to start blocking the connections suddenly.
Sometimes it appears to be state related:

(44.18 is the squid server (trident), 37.163 is the system running portsnap (ice))

Oct  5 11:22:03 jolly-fw1 kernel: pf: BAD state: TCP 35.9.44.18:3128 35.9.44.18:3128 35.9.37.163:55357 
[lo=646710754 high=646777361 win=33304 modulator=0 wscale=1] [lo=4033525074 high=4033590770 win=33304 
modulator=0 wscale=1] 9:9 S seq=650709460 ack=4033525074 len=0 ackskew=0 pkts=5:4 dir=in,fwd
Oct  5 11:22:03 jolly-fw1 kernel: pf: State failure on: 1       | 5
Oct  5 11:22:06 jolly-fw1 kernel: pf: BAD state: TCP 35.9.44.18:3128 35.9.44.18:3128 35.9.37.163:55357 
[lo=646710754 high=646777361 win=33304 modulator=0 wscale=1] [lo=4033525074 high=4033590770 win=33304 
modulator=0 wscale=1] 9:9 S seq=650709460 ack=4033525074 len=0 ackskew=0 pkts=5:4 dir=in,fwd
Oct  5 11:22:06 jolly-fw1 kernel: pf: State failure on: 1       | 5
Oct  5 11:22:09 jolly-fw1 kernel: pf: BAD state: TCP 35.9.44.18:3128 35.9.44.18:3128 35.9.37.163:55357 
[lo=646710754 high=646777361 win=33304 modulator=0 wscale=1] [lo=4033525074 high=4033590770 win=33304 
modulator=0 wscale=1] 9:9 S seq=650709460 ack=4033525074 len=0 ackskew=0 pkts=5:4 dir=in,fwd
Oct  5 11:22:09 jolly-fw1 kernel: pf: State failure on: 1       | 5
Oct  5 11:22:12 jolly-fw1 kernel: pf: BAD state: TCP 35.9.44.18:3128 35.9.44.18:3128 35.9.37.163:55357 
[lo=646710754 high=646777361 win=33304 modulator=0 wscale=1] [lo=4033525074 high=4033590770 win=33304 
modulator=0 wscale=1] 9:9 S seq=650709460 ack=4033525074 len=0 ackskew=0 pkts=5:4 dir=in,fwd
Oct  5 11:22:12 jolly-fw1 kernel: pf: State failure on: 1       | 5

I am using:
set state-policy if-bound
set timeout { tcp.closed 15 }

pfctl -sr shows:
scrub in on em0 all no-df random-id min-ttl 10 max-mss 1460 fragment reassemble
scrub out on em0 all no-df random-id min-ttl 10 max-mss 1460 fragment reassemble
block drop in log quick on em0 proto tcp all flags /S
block drop in log quick on em0 proto tcp all flags /FSRA
block drop in log quick on em0 proto tcp all flags /FSRAU
block drop in log quick on em0 proto tcp all flags A/A
block drop in log quick on em0 proto tcp all flags F/FSRA
block drop in log quick on em0 proto tcp all flags U/FSRAU
block drop in log quick on em0 proto tcp all flags FS/FS
block drop in log quick on em0 proto tcp all flags FS/FSRA
block drop in log quick on em0 proto tcp all flags SR/SR
block drop in log quick on em0 proto tcp all flags FPU/FPU
block drop in log quick on em0 proto tcp all flags FPU/FSRPAUEW
block drop in log quick on em0 proto tcp all flags FSRAU/FSRAU
block drop in log quick on em0 proto tcp all flags FSRPAU/FSRPAU
pass quick on lo0 all
pass quick on em1 all
block drop log-all on em0 all
pass in quick on em0 inet proto tcp from any to 35.9.44.100 port = ssh flags S/SA keep state (if-bound)
pass in quick on em0 inet proto tcp from any to 35.9.44.18 port = ssh flags S/SA keep state (if-bound)
pass in quick on em0 inet proto tcp from any to 35.9.44.18 port = 3128 flags S/SA keep state (if-bound)
pass out on em0 inet proto icmp all icmp-type echoreq keep state (if-bound)
pass in on em0 inet proto icmp all icmp-type echoreq keep state (if-bound)
pass out on em0 proto tcp all keep state (if-bound)
pass out on em0 proto udp all keep state (if-bound)

At the time of the stall, I had 285 state entries according to pfctl -sr.
276 of them were to port 3128, and all 276 were FIN_WAIT_2:FIN_WAIT_2 including
for port 55357:
em0 tcp 35.9.44.18:3128 <- 35.9.37.163:55357       FIN_WAIT_2:FIN_WAIT_2
em0 is the external facing interface, em1 is directly connected to the squid server.

I think this is the relevant part from the packet capture, I filtered on
port 55357 because of the state failures above and because I could see
tcp retries at the very end of the trace.  The trace was started at 1160061707.897973,
therefore most of the events below happened at 11 seconds, followed by 15, 18, 21s 
for the last three packets.  

1160061719.730940 IP (tos 0x0, ttl  63, id 51535, offset 0, flags [DF], proto: TCP (6), length: 64) 
ice.egr.msu.edu.55357 > trident.egr.msu.edu.3128: S, cksum 0xd2c5 (correct), 646710499:646710499(0) win 65535 
<mss 1460,nop,wscale 1,nop,nop,timestamp 265399486 0,sackOK,eol>
1160061719.731150 IP (tos 0x0, ttl  64, id 38901, offset 0, flags [none], proto: TCP (6), length: 64) 
trident.egr.msu.edu.3128 > ice.egr.msu.edu.55357: S, cksum 0xb79c (correct), 4033524160:4033524160(0) ack 
646710500 win 65535 <mss 1460,nop,wscale 1,nop,nop,timestamp 2075196731 265399486,sackOK,eol>
1160061719.731431 IP (tos 0x0, ttl  63, id 51536, offset 0, flags [DF], proto: TCP (6), length: 52) 
ice.egr.msu.edu.55357 > trident.egr.msu.edu.3128: ., cksum 0x754f (correct), ack 1 win 33304 
<nop,nop,timestamp 265399486 2075196731>
1160061719.731441 IP (tos 0x0, ttl  63, id 51537, offset 0, flags [DF], proto: TCP (6), length: 305) 
ice.egr.msu.edu.55357 > trident.egr.msu.edu.3128: P, cksum 0xd903 (correct), 1:254(253) ack 1 win 33304 
<nop,nop,timestamp 265399486 2075196731>
1160061719.777369 IP (tos 0x0, ttl  64, id 32422, offset 0, flags [none], proto: TCP (6), length: 964) 
trident.egr.msu.edu.3128 > ice.egr.msu.edu.55357: P, cksum 0xe6b1 (correct), 1:913(912) ack 254 win 33304 
<nop,nop,timestamp 2075196777 265399486>
1160061719.777380 IP (tos 0x0, ttl  64, id 51616, offset 0, flags [none], proto: TCP (6), length: 52) 
trident.egr.msu.edu.3128 > ice.egr.msu.edu.55357: F, cksum 0x7093 (correct), 913:913(0) ack 254 win 33304 
<nop,nop,timestamp 2075196777 265399486>
1160061719.777656 IP (tos 0x0, ttl  63, id 51539, offset 0, flags [DF], proto: TCP (6), length: 52) 
ice.egr.msu.edu.55357 > trident.egr.msu.edu.3128: ., cksum 0x722d (correct), ack 914 win 32848 
<nop,nop,timestamp 265399532 2075196777>
1160061719.778030 IP (tos 0x0, ttl  63, id 51540, offset 0, flags [DF], proto: TCP (6), length: 52) 
ice.egr.msu.edu.55357 > trident.egr.msu.edu.3128: F, cksum 0x722b (correct), 254:254(0) ack 914 win 32848 
<nop,nop,timestamp 265399533 2075196777>
1160061719.778240 IP (tos 0x0, ttl  64, id 8633, offset 0, flags [none], proto: TCP (6), length: 52) 
trident.egr.msu.edu.3128 > ice.egr.msu.edu.55357: ., cksum 0x7063 (correct), ack 255 win 33303 
<nop,nop,timestamp 2075196778 265399533>
1160061722.978289 IP (tos 0x0, ttl  63, id 52907, offset 0, flags [DF], proto: TCP (6), length: 64) 
ice.egr.msu.edu.55357 > trident.egr.msu.edu.3128: S, cksum 0xc0e8 (correct), 650709460:650709460(0) win 65535 
<mss 1460,nop,wscale 1,nop,nop,timestamp 265402733 0,sackOK,eol>
1160061725.978171 IP (tos 0x0, ttl  63, id 52924, offset 0, flags [DF], proto: TCP (6), length: 64) 
ice.egr.msu.edu.55357 > trident.egr.msu.edu.3128: S, cksum 0xb530 (correct), 650709460:650709460(0) win 65535 
<mss 1460,nop,wscale 1,nop,nop,timestamp 265405733 0,sackOK,eol>
1160061729.178434 IP (tos 0x0, ttl  63, id 53941, offset 0, flags [DF], proto: TCP (6), length: 64) 
ice.egr.msu.edu.55357 > trident.egr.msu.edu.3128: S, cksum 0xa8b0 (correct), 650709460:650709460(0) win 65535 
<mss 1460,nop,wscale 1,nop,nop,timestamp 265408933 0,sackOK,eol>

This issue has been plaguing me for as long as I can remember but I just haven't sat down
and reported it yet, tried to debug it by myself.  I don't think I have any unusual kernel
sysctl tweaks enabled, just the defaults.  I think this indicates a bigger issue than just
portsnap which I need to understand better before I can deploy a pf firewall infront of 
bigger networks with more diverse traffic.  I'd appreciate some help.  I suspect a tcp port
is perhaps being reused too quickly, but I haven't quite caught it.  Let me know if I can
provide more information or do further testing.  Thanks.

I have posted the pfctl -ss output, and a tcpdump pcap dump of the session to:
http://www.egr.msu.edu/~mcdouga9/state5-ice
http://www.egr.msu.edu/~mcdouga9/pkts-portsnap1-ice.gz

More information about the freebsd-pf mailing list