On Dec 23 20:17:23, Jan Stary wrote:
> >>>> 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.)
This is possibly a misunderstanding:
> 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.
"tcp.closing: The state after the first FIN has been sent."
That does not mean the first FIN _we_ sent. The first FIN
was sent by the other side, at 13:08:07.
The state we are in now _is_ tcp.closing, right? The first FIN has been
sent. It's not "tcp.finwait: the state after both FINs have been exchanged",
right? Because the FINs have not been exchanged - our FIN has not been ACKed.
Or does pf consider this finwait already, because we have acked the remote
FIN, and sent our FIN?
Either way, this packet is not the first one to go over tcp.finwait = 45s.
(And it is well withnin tcp.closing = 900s.) So why is this the first
one that got blocked?
Thank you for your time
Jan
