Date: Tue, 4 Mar 2008 11:43:37 +0200 From: Silver Salonen <silver.salonen@gmail.com> To: freebsd-pf@freebsd.org Subject: Re: occasional "Operation not permitted" on state-mismatch Message-ID: <200803041143.37873.silver.salonen@gmail.com> In-Reply-To: <200712180934.58755.silver.salonen@gmail.com> References: <200712180934.58755.silver.salonen@gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
On Tuesday 18 December 2007 09:34, Silver Salonen wrote: > Sometimes I get just some connection timeout: CRITICAL - Socket timeout after > 2 seconds (I don't know what could cause that). > > I can see this behaviour in about every FreeBSD/PF machine I have. Hello. I'm still sitting on this error. It hasn't been so urgent as it's working quite OK, so I've been busy with other things. On testing the connection with Nagios plugin check_tcp to port 22, I've got the timeouts every minute or so - actually it's quite random and depends on traffic activity. The tcpdump shows that a packet leaves one side but never reaches the other. This one seems not to be related to the state-mismatch issue, as the counter doesn't increase or anything. I set pfctl debugging do 'loud', but I see nothing appearing in log at the time I get timeout. Some observations - connection from port 57733 is successful, but connection from port 57734 times out. * tcpdump on external interface SRC: ===== 11:21:07.358157 IP src-bsd.57733 > dst-bsd.ssh: S 57016355:57016355(0) win 65535 <mss 1460,nop,wscale 1,nop,nop,timestamp 3213863661 0,sackOK,eol> 11:21:07.380850 IP dst-bsd.ssh > src-bsd.57733: S 3006112695:3006112695(0) ack 57016356 win 65535 <mss 1460,nop,wscale 1,nop,nop,timestamp 701162218 3213863661,sackOK,eol> 11:21:07.381137 IP src-bsd.57733 > dst-bsd.ssh: . ack 1 win 33304 <nop,nop,timestamp 3213863684 701162218> 11:21:07.381302 IP src-bsd.57733 > dst-bsd.ssh: F 1:1(0) ack 1 win 33304 <nop,nop,timestamp 3213863685 701162218> 11:21:07.401295 IP dst-bsd.ssh > src-bsd.57733: . ack 2 win 33304 <nop,nop,timestamp 701162238 3213863685> 11:21:07.414093 IP dst-bsd.ssh > src-bsd.57733: P 1:40(39) ack 2 win 33304 <nop,nop,timestamp 701162251 3213863685> 11:21:07.414320 IP src-bsd.57733 > dst-bsd.ssh: R 57016357:57016357(0) win 0 11:21:07.414333 IP dst-bsd.ssh > src-bsd.57733: F 40:40(0) ack 2 win 33304 <nop,nop,timestamp 701162251 3213863685> 11:21:07.414373 IP src-bsd.57733 > dst-bsd.ssh: R 57016357:57016357(0) win 0 11:21:08.445833 IP src-bsd.57734 > dst-bsd.ssh: S 3894885836:3894885836(0) win 65535 <mss 1460,nop,wscale 1,nop,nop,timestamp 3213864749 0,sackOK,eol> ===== DST: ===== 11:21:07.354764 IP src-bsd.57733 > dst-bsd.ssh: S 57016355:57016355(0) win 65535 <mss 1460,nop,wscale 1,nop,nop,timestamp 3213863661 0,sackOK,eol> 11:21:07.354849 IP dst-bsd.ssh > src-bsd.57733: S 3006112695:3006112695(0) ack 57016356 win 65535 <mss 1460,nop,wscale 1,nop,nop,timestamp 701162218 3213863661,sackOK,eol> 11:21:07.368066 IP src-bsd.57733 > dst-bsd.ssh: . ack 1 win 33304 <nop,nop,timestamp 3213863684 701162218> 11:21:07.374921 IP src-bsd.57733 > dst-bsd.ssh: F 1:1(0) ack 1 win 33304 <nop,nop,timestamp 3213863685 701162218> 11:21:07.375032 IP dst-bsd.ssh > src-bsd.57733: . ack 2 win 33304 <nop,nop,timestamp 701162238 3213863685> 11:21:07.387897 IP dst-bsd.ssh > src-bsd.57733: P 1:40(39) ack 2 win 33304 <nop,nop,timestamp 701162251 3213863685> 11:21:07.388215 IP dst-bsd.ssh > src-bsd.57733: F 40:40(0) ack 2 win 33304 <nop,nop,timestamp 701162251 3213863685> 11:21:07.440012 IP src-bsd.57733 > dst-bsd.ssh: R 57016357:57016357(0) win 0 11:21:07.440187 IP src-bsd.57733 > dst-bsd.ssh: R 57016357:57016357(0) win 0 ===== * tcpdump on pflog0 For observing action from PF point of view, I set logging on these rules: SRC: ===== pass out log on $ext_if proto tcp all modulate state queue(std, tcp_ack) ===== DST: ===== block log all pass in log on $ext_if proto tcp from $src to ($ext_if) port ssh pass out log on $ext_if proto tcp from ($ext_if) port ssh to any queue (ssh_bulk ssh_login) pass in log on $ext_if proto tcp from $src to ($ext_if) port ssh queue ssh ===== So 'tcpdump -i pflog0 -nettt' shows: SRC: ===== 1. 082479 rule 19/0(match): pass out on fxp0: src-bsd.57733 > dst-bsd.22: S 2351929505:2351929505(0) win 65535 <mss 1460,nop,wscale 1,[|tcp]> 1. 087715 rule 19/0(match): pass out on fxp0: src-bsd.57734 > dst-bsd.22: S 4213894461:4213894461(0) win 65535 <mss 1460,nop,wscale 1,[|tcp]> ===== DST: ===== 1. 010760 rule 186/0(match): pass in on fxp0: src-bsd.57733 > dst-bsd.22: S 57016355:57016355(0) win 65535 <mss 1460,nop,wscale 1,[|tcp]> 000025 rule 184/0(match): pass out on fxp0: dst-bsd.22 > src-bsd.57733: S 3006112695:3006112695(0) ack 57016356 win 65535 <mss 1460,nop,wscale 1,[| tcp]> 013247 rule 186/0(match): pass in on fxp0: src-bsd.57733 > dst-bsd.22: . ack 1 win 33304 <nop,nop,timestamp 3213863684[|tcp]> 006913 rule 186/0(match): pass in on fxp0: src-bsd.57733 > dst-bsd.22: F 1:1 (0) ack 1 win 33304 <nop,nop,timestamp 3213863685[|tcp]> 000022 rule 184/0(match): pass out on fxp0: dst-bsd.22 > src-bsd.57733: . ack 2 win 33304 <nop,nop,timestamp 701162238[|tcp]> 012858 rule 184/0(match): pass out on fxp0: dst-bsd.22 > src-bsd.57733: P 1:40 (39) ack 2 win 33304 <nop,nop,timestamp 701162251[|tcp]> 000324 rule 184/0(match): pass out on fxp0: dst-bsd.22 > src-bsd.57733: F 40:40(0) ack 2 win 33304 <nop,nop,timestamp 701162251[|tcp]> 051836 rule 186/0(match): pass in on fxp0: src-bsd.57733 > dst-bsd.22: R 57016357:57016357(0) win 0 000162 rule 186/0(match): pass in on fxp0: src-bsd.57733 > dst-bsd.22: R 57016357:57016357(0) win 0 ===== Any suggestions where the packet is getting lost or how should I debug it further? -- Silver
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200803041143.37873.silver.salonen>