Firewall gets into bad state - cannot establish connections
-
Periodically one of our firewalls (the one that has been updated to 2.4.4) prevents outgoing TCP connections to the internet from getting established. Here is a step by step of what I see. Packet comes into LAN interface:
14:12:03.430358 IP vulcan7.cora.nwra.com.37330 > wolfe.freenode.net.ircs-u: Flags [S], seq 3430505508, win 29200, options [mss 1460,sackOK,TS val 779062841 ecr 0,nop,wscale 7], length 0
Goes out WAN and reply comes in WAN:
14:12:03.430419 IP inferno.cora.nwra.com.12004 > wolfe.freenode.net.ircs-u: Flags [S], seq 3430505508, win 29200, options [mss 1460,sackOK,TS val 779062841 ecr 0,nop,wscale 7], length 0 14:12:03.569838 IP wolfe.freenode.net.ircs-u > inferno.cora.nwra.com.12004: Flags [S.], seq 3688906824, ack 3430505509, win 28960, options [mss 1460,sackOK,TS val 2378716153 ecr 779062841,nop,wscale 7], length 0
pf -x lound message reports:
Dec 20 14:12:03 inferno kernel: pf: OK ICMP 3:1 204.134.157.90 -> 193.10.255.100 state: TCP out wire: 193.10.255.100:6697 204.134.157.90:12004 stack: 193.10.255.100:6697 10.10.41.27:37330 [lo=3430505508 high=3430534565 win=229 modulator=0 wscale=7] [lo=3688906825 high=3688936137 win=227 modulator=0 wscale=7] 4:2 seq=3688906824
Which corresponds to the initial outgoing sequence number. I'm guessing this is just a normal debug message indicating that the state is being created or some such. However, that reply never goes out the LAN interface. tcpdump on the lan interface just shows:
14:12:03.430358 IP vulcan7.cora.nwra.com.37330 > wolfe.freenode.net.ircs-u: Flags [S], seq 3430505508, win 29200, options [mss 1460,sackOK,TS val 779062841 ecr 0,nop,wscale 7], length 0 14:12:04.432775 IP vulcan7.cora.nwra.com.37330 > wolfe.freenode.net.ircs-u: Flags [S], seq 3430505508, win 29200, options [mss 1460,sackOK,TS val 779063844 ecr 0,nop,wscale 7], length 0
which is the initial packet followed by its retransmission since the client never got the reply.
pfctl -s state shows:igb0 tcp 193.10.255.100:6697 <- 10.10.41.27:37330 SYN_SENT:ESTABLISHED igb5 tcp 204.134.157.90:12004 (10.10.41.27:37330) -> 193.10.255.100:6697 ESTABLISHED:SYN_SENT
which I can't really parse.
So this plays out a little further on the WAN interface:14:12:04.432796 IP inferno.cora.nwra.com.12004 > wolfe.freenode.net.ircs-u: Flags [S], seq 3430505508, win 29200, options [mss 1460,sackOK,TS val 779063844 ecr 0,nop,wscale 7], length 0 14:12:04.572141 IP wolfe.freenode.net.ircs-u > inferno.cora.nwra.com.12004: Flags [S.], seq 3704566815, ack 3430505509, win 28960, options [mss 1460,sackOK,TS val 2378716404 ecr 779063844,nop,wscale 7], length 0
This is the retransmission of the initial SYN packet followed by a response. The sequence # of the response is greater than before. And we get this in the log:
Dec 20 14:12:04 inferno kernel: pf: BAD state: TCP out wire: 193.10.255.100:6697 204.134.157.90:12004 stack: 193.10.255.100:6697 10.10.41.27:37330 [lo=3430505509 high=3430534565 win=29200 modulator=0 wscale=7] [lo=3688906825 high=3688936137 win=227 modulator=0 wscale=7] 4:2 SA seq=3704566815 (3704566815) ack=3430505509 len=0 ackskew=0 pkts=3:1 dir=in,rev
Which seems to be the firewall rejecting that reply packet because it doesn't match the established state? These packets and messages repeat for while until both sides give up. Currently this connection has failed to be established for a couple hours now, but I expect at some point for it to work again.
Has something changed for the firewall state machine to be more picky about packets? -
Maybe that initial "pf: OK ICMP" message is an indication of a problem though. On a successful connection I do not seem to see one.
-
Looks like the "pf: OK IMCP" message is generated when pf successfully sends an ICMP response in response to an incoming packet:
if (V_pf_status.debug >= PF_DEBUG_MISC) { printf("pf: OK ICMP %d:%d ", icmptype, pd->hdr.icmp->icmp_code); pf_print_host(pd->src, 0, pd->af); printf(" -> "); pf_print_host(pd->dst, 0, pd->af); printf(" state: "); pf_print_state(*state); printf(" seq=%u\n", seq); }
So it's sending a "Destination unreachable":"Host unreachable" message it seems. Now, why is that packet being rejected?
-
This can also happen to established connections:
4741 12782.209458 204.134.157.90 -> 192.186.157.43 TCP 111 40938 > ircs-u [PSH, ACK] Seq=18652 Ack=99697 Win=1424 Len=45 TSval=861734345 TSecr=1555692980 4742 12782.254633 192.186.157.43 -> 204.134.157.90 TCP 153 ircs-u > 40938 [PSH, ACK] Seq=99697 Ack=18697 Win=260 Len=87 TSval=1555707731 TSecr=861734345 4743 12782.453911 204.134.157.90 -> 192.186.157.43 TCP 111 [TCP Retransmission] 40938 > ircs-u [PSH, ACK] Seq=18652 Ack=99697 Win=1424 Len=45 TSval=861734590 TSecr=1555692980 4744 12782.497753 192.186.157.43 -> 204.134.157.90 TCP 78 [TCP Dup ACK 4742#1] ircs-u > 40938 [ACK] Seq=99784 Ack=18697 Win=260 Len=0 TSval=1555707792 TSecr=861734590 SLE=18652 SRE=18697 4745 12782.497813 204.134.157.90 -> 192.186.157.43 ICMP 106 Destination unreachable (Host unreachable)
Interestingly it does not look like pfsense generated an ICMP Destination unreachable for the first packet that was not forwarded. Only after the retransmissions started does it start actively blocking packets (or at least informing the sender about it).
-
How can I keep the "pfctl -x loud" setting active?