>>>> Speculation: this looks to me like an end of a valid http session:
>>>> an internal clients reads a web page, and probably a few images,
>>>> everything goes through, but the last FIN does not. The first SYN
>>>> creates state that lets the subsequent packets through. Doesn't the
>>>> last FIN belong to the same state? Also, this is an outgoing packet,
>>>> which I explicitly allow.
>>>> What can possibly be blocking these FIN packets?
On Dec 23 02:39:59, Daniel E. Hassler wrote:
> Timing. State has probably timed out before the blocked packets are
> received. Log the whole conversation - both ways for both Firefox and
> lynx.
On Dec 23 04:45:04, Brian Seklecki (Mobile) wrote:
> set timeout tcp.finwait 900
> set timeout tcp.closing 900
You are both probably right. Thank you.
With lynx (that is, an internal client runs 'lynx www.ihned.cz')
the conversation looks like this (tcpdump follows): two tcp connections
are made (first receives 302 Found, the second one receives 200);
the data is read; both connections are correctly FIN'd, the FINs
are ack'd. No packets get blocked.
12:36:57.989903 mac.stare.cz.54703 > www.ihned.cz.www: S
2635202717:2635202717(0) win 65535 <mss 1460,nop,wscale 3,nop,nop,timestamp
743703535 0,sackOK,eol> (DF)
12:36:58.006316 www.ihned.cz.www > mac.stare.cz.54703: S
2401821844:2401821844(0) ack 2635202718 win 5792 <mss 1380,sackOK,timestamp
3998698463 743703535,nop,wscale 7>
12:36:58.006483 mac.stare.cz.54703 > www.ihned.cz.www: . ack 1 win 65535
<nop,nop,timestamp 743703535 3998698463> (DF)
12:36:58.006979 mac.stare.cz.54703 > www.ihned.cz.www: P 1:303(302) ack 1 win
65535 <nop,nop,timestamp 743703535 3998698463> (DF)
12:36:58.018389 www.ihned.cz.www > mac.stare.cz.54703: . ack 303 win 54
<nop,nop,timestamp 3998698464 743703535>
12:36:58.036406 www.ihned.cz.www > mac.stare.cz.54703: P 1:169(168) ack 303 win
54 <nop,nop,timestamp 3998698466 743703535>
12:36:58.036774 mac.stare.cz.54703 > www.ihned.cz.www: . ack 169 win 65535
<nop,nop,timestamp 743703535 3998698466> (DF)
12:36:58.036920 www.ihned.cz.www > mac.stare.cz.54703: F 169:169(0) ack 303 win
54 <nop,nop,timestamp 3998698466 743703535>
12:36:58.037094 mac.stare.cz.54703 > www.ihned.cz.www: . ack 170 win 65535
<nop,nop,timestamp 743703535 3998698466> (DF)
12:36:58.037990 mac.stare.cz.54703 > www.ihned.cz.www: F 303:303(0) ack 170 win
65535 <nop,nop,timestamp 743703535 3998698466> (DF)
12:36:58.046266 www.ihned.cz.www > mac.stare.cz.54703: . ack 304 win 54
<nop,nop,timestamp 3998698467 743703535>
(The first connection which received 302 Found ends here;
the other one starts now.)
12:37:00.040373 mac.stare.cz.54704 > www.ihned.cz.www: S
3284050248:3284050248(0) win 65535 <mss 1460,nop,wscale 3,nop,nop,timestamp
743703555 0,sackOK,eol> (DF)
12:37:00.052042 www.ihned.cz.www > mac.stare.cz.54704: S
3325100471:3325100471(0) ack 3284050249 win 5792 <mss 1380,sackOK,timestamp
3998698668 743703555,nop,wscale 7>
12:37:00.052393 mac.stare.cz.54704 > www.ihned.cz.www: . ack 1 win 65535
<nop,nop,timestamp 743703556 3998698668> (DF)
12:37:00.053022 mac.stare.cz.54704 > www.ihned.cz.www: P 1:299(298) ack 1 win
65535 <nop,nop,timestamp 743703556 3998698668> (DF)
12:37:00.061764 www.ihned.cz.www > mac.stare.cz.54704: . ack 299 win 54
<nop,nop,timestamp 3998698669 743703556>
[...]
12:37:00.220313 www.ihned.cz.www > mac.stare.cz.54704: . 82081:83449(1368) ack
299 win 54 <nop,nop,timestamp 3998698682 743703557>
12:37:00.220486 www.ihned.cz.www > mac.stare.cz.54704: . 83449:84817(1368) ack
299 win 54 <nop,nop,timestamp 3998698682 743703557>
12:37:00.220539 www.ihned.cz.www > mac.stare.cz.54704: FP 84817:84919(102) ack
299 win 54 <nop,nop,timestamp 3998698682 743703557>
12:37:00.220620 mac.stare.cz.54704 > www.ihned.cz.www: . ack 82081 win 65535
<nop,nop,timestamp 743703557 3998698682> (DF)
12:37:00.220858 mac.stare.cz.54704 > www.ihned.cz.www: . ack 84920 win 65309
<nop,nop,timestamp 743703557 3998698682> (DF)
12:37:00.222642 mac.stare.cz.54704 > www.ihned.cz.www: F 299:299(0) ack 84920
win 65535 <nop,nop,timestamp 743703557 3998698682> (DF)
12:37:00.229482 www.ihned.cz.www > mac.stare.cz.54704: . ack 300 win 54
<nop,nop,timestamp 3998698686 743703557>
With firefox on the other hand, this is what happens: six connections
are made (ports 54748-54753) to get the page itself and the css and the
images. Data is read on the connections; then the remote end sends
a FIN for one of these connections (I am isolating port 54768; the very
same happens on the other ports, too):
[...]
13:08:07.915873 www.ihned.cz.www > mac.stare.cz.54748: F 517:517(0) ack 637 win
56 <nop,nop,timestamp 3992488807 743721564>
The internal client ACKs the FIN ...
13:08:07.916238 mac.stare.cz.54748 > www.ihned.cz.www: . ack 518 win 65535
<nop,nop,timestamp 743722213 3992488807> (DF)
and sends its own FIN later:
13:08:21.284154 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743722346 3992488807> (DF)
Comparing the timestamps, that's fourteen seconds after the client
sent the ACK for the remote FIN. That should be soon enough:
# pfctl -s timeouts | fgrep tcp
tcp.first 120s
tcp.opening 30s
tcp.established 86400s
tcp.closing 900s
tcp.finwait 45s
tcp.closed 90s
tcp.tsdiff 30s
This FIN is *not* blocked, it goes out. However, no ACK is received
from the remote side for this FIN (why?). So the internal client sends
its FIN again a few times:
13:08:22.186559 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743722355 3992488807> (DF)
13:08:24.188168 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743722375 3992488807> (DF)
13:08:28.192462 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743722415 3992488807> (DF)
13:08:36.202517 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743722495 3992488807> (DF)
13:08:52.221585 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743722655 3992488807> (DF)
13:09:24.267275 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743722975 3992488807> (DF)
All of these FINs go through, but never receive an ACK (why?).
Then, these FINs start to get blocked. First such is
13:10:28.363318 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743723615 3992488807> (DF)
The corresponding line from 'tcpdump -e -i pflog0' is
13:10:28.363655 rule 15/(match) block in on vr1: mac.stare.cz.54748 >
www.ihned.cz.www: F 4189102151:4189102151(0) ack 1081156646 win 65535
<nop,nop,timestamp 743723615 3992488807> (DF)
(I am assuming it is the same packet, as the timestamp differs by
less then a milisecond.)
The first FIN we tried to send was at 13:08:21; tcp.closing is 900s;
(tcp.closing: The state after the first FIN has been sent.) So we
are well within the timeout.
So, before I bump up tcp.closing and tcp.finwait: why is it that
the packets start to get blocked right now?
Is tcp.finwait relevant to this?
tcp.finwait: The state after both FINs have been exchanged and the
connection is closed. Some hosts (notably web servers on Solaris)
send TCP packets even after closing the connection. Increasing
tcp.finwait (and possibly tcp.closing) can prevent blocking of such
packets.
(This is not the problem I have.)
The same happens again five times (again, I assume these lines from the
tcpdump of the session correspond to the tcpdump lines of pflog0, each
being within a milisecond of the respective other):
13:11:32.455182 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743724255 3992488807> (DF)
13:12:36.546227 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743724895 3992488807> (DF)
13:13:40.634453 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743725535 3992488807> (DF)
13:14:44.727213 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743726175 3992488807> (DF)
13:15:48.825336 mac.stare.cz.54748 > www.ihned.cz.www: F 637:637(0) ack 518 win
65535 <nop,nop,timestamp 743726815 3992488807> (DF)
13:11:32.455586 rule 15/(match) block in on vr1: mac.stare.cz.54748 >
www.ihned.cz.www: F 0:0(0) ack 1 win 65535 <nop,nop,timestamp 743724255
3992488807> (DF)
13:12:36.546531 rule 15/(match) block in on vr1: mac.stare.cz.54748 >
www.ihned.cz.www: F 0:0(0) ack 1 win 65535 <nop,nop,timestamp 743724895
3992488807> (DF)
13:13:40.634816 rule 15/(match) block in on vr1: mac.stare.cz.54748 >
www.ihned.cz.www: F 0:0(0) ack 1 win 65535 <nop,nop,timestamp 743725535
3992488807> (DF)
13:14:44.727553 rule 15/(match) block in on vr1: mac.stare.cz.54748 >
www.ihned.cz.www: F 0:0(0) ack 1 win 65535 <nop,nop,timestamp 743726175
3992488807> (DF)
13:15:48.825642 rule 15/(match) block in on vr1: mac.stare.cz.54748 >
www.ihned.cz.www: F 0:0(0) ack 1 win 65535 <nop,nop,timestamp 743726815
3992488807> (DF)
Eventually, the client gives up and send a RST:
13:16:52.920592 mac.stare.cz.54748 > www.ihned.cz.www: R 638:638(0) ack 518 win
65535 (DF)
That gets blocked too:
13:16:52.920905 rule 15/(match) block in on vr1: mac.stare.cz.54748 >
www.ihned.cz.www: R 1:1(0) ack 1 win 65535 (DF)
Just to rule out the possibility that it is the remote server
which is misbehaving (not ACKing my client's FIN): I experience
the same with any outside server, such as www.openbsd.org.
> Your client, if its really a mac, may have a sysctl like
> ...net.inet.tcp.finwait2_timeout: 60000
> ... net.inet.tcp.finwait2_timeout: FIN-WAIT2 timeout
It's a MacOSX 10.5.8. It doesn't have any such sysctl; but I need
to look more closely yet on macos network stack.
Thank you for the insight
Jan
