conntrackd: synchronization failures

conntrackd: synchronization failures

[Jiri Kosina]

Hi,

I've tried to use conntrackd to provide full connection tracking for 
firewalling and NAT in an asymmetric routing situation, but unfortunately 
the synchronization is failing quite often.

The setup is rather simple:

		  /  Internet  \
		 /		\
		RS1 <conntrackd> RS2
		   \	       /
		     \	LAN /
			
RS1 and RS2 have the same netfilter rules applied. RS1 is mostly used for 
sending outgoing traffic from LAN to Internet, while RS2 is mostly used 
for packets coming from Internet to LAN (LAN is mostly "consumer", so the 
Internet->LAN traffic is of a much higher volume (~1Gbps spikes) compared 
to ~200Mbps of outgoing traffic).

RS1 and RS2 are connected via direct link (~0.06ms) which is reserved for 
conntrackd.

conntrackd.conf can be found below.

The issues:

- minor: every few minutes, error message of either of the two forms below 
  appears in the log

	(pid=11083) [ERROR] inject-add2: File exists
	        tcp      6 120 FIN_WAIT src=10.33.12.15 dst=116.31.116.30 sport=22 dport=44232 [ASSURED]
	(pid=11083) [ERROR] inject-add2: Device or resource busy
		tcp      6 300 CLOSE src=10.33.40.102 dst=216.58.201.110 sport=53660 dport=443 [UNREPLIED]

  etc. (states, IPs, ports differ).

- major: roughly once in a few hours the frequency of these messages on 
  one of the router (usually RS2) starts spitting the 'File exists' messages
  much more frequently, and the traffic on the dedicated link 
  dramatically decreases for some reason (IOW conntrackds stop syncing as 
  they were before, while the actual 'data' traffic between LAN and 
  Internet is still the same). This is how the traffic on dedicated link 
  looks like when the issue appears:

	http://www.jikos.cz/jikos/junk/conntrackd.jpg

  the down-spike is where connections between LAN and Internet start to 
  fail (no ACKs coming back from SYNs, etc, as RS2 is dropping everything 
  due to conntrack being out of sync), and the up-spike, bringing things 
  back to normal, is where either conntrackd is restarted, or the incoming
  traffic is cut (by shutting BGP sessions down).

I don't really have a good trial-test environment, as this is happening on 
a production network that is hard to emulate.

Any ideas what might be causing this, or any hints to to efficiently (and 
non-disruptively) debug the issue?

Thanks,

-- 
Jiri Kosina <jikos@kernel.org>
SUSE Labs

Re: conntrackd: synchronization failures

[Jiri Kosina]

On Wed, 11 Jan 2017, Jiri Kosina wrote:

> conntrackd.conf can be found below.

.. and now actually included, sorry.

BTW NetlinkOverrunResync and NetlinkEventsReliable don't have any 
significant impact on the issue.


=== cut here ===
Sync {
	Mode FTFW {
		DisableExternalCache On
	}

	UDP {
		IPv4_address 10.33.28.13
		IPv4_Destination_Address 10.33.28.14
		Port 3780
		Interface eth2
	}

}

General {
	Nice -20
	HashSize 32768
	HashLimit 1024000
	LogFile on
	LockFile /var/lock/conntrack.lock
	UNIX {
		Path /var/run/conntrackd.ctl
		Backlog 20
	}
	NetlinkBufferSize 2097152
	NetlinkBufferSizeMaxGrowth 33554432
	NetlinkOverrunResync Off
	NetlinkEventsReliable On

	Filter From Userspace {
		Protocol Accept {
			TCP
			SCTP
			DCCP
			UDP
			ICMP
			IPv6-ICMP
		}
		Address Ignore {
			IPv4_address 127.0.0.1 # loopback
	}
}
=== cut here ===

-- 
Jiri Kosina <jikos@kernel.org>
SUSE Labs

Re: conntrackd: synchronization failures

[Jiri Kosina]

On Wed, 11 Jan 2017, Jiri Kosina wrote:

> 	(pid=11083) [ERROR] inject-add2: File exists

Sometimes this EEXIST is reported in inject-add1

> 	        tcp      6 120 FIN_WAIT src=10.33.12.15 dst=116.31.116.30 sport=22 dport=44232 [ASSURED]
> 	(pid=11083) [ERROR] inject-add2: Device or resource busy

This EBUSY seems to be always inject-add2 phase though.

I've tried both conntrackd 1.0.1 and 1.4.3, both compiled against 
libnfnetlink-1.0.1; the behavior has been exactly the same.

The hosts are running rather different kernels (3.10 from RHEL 7 (RS2) and 
4.6.1-rt2 (RS1) respectively).

-- 
Jiri Kosina <jikos@kernel.org>
SUSE Labs

Re: conntrackd: synchronization failures

[Arturo Borrero Gonzalez]

On 11 January 2017 at 22:57, Jiri Kosina <jikos@kernel.org> wrote:
> On Wed, 11 Jan 2017, Jiri Kosina wrote:
>
>>       (pid=11083) [ERROR] inject-add2: File exists
>
> Sometimes this EEXIST is reported in inject-add1
>
>>               tcp      6 120 FIN_WAIT src=10.33.12.15 dst=116.31.116.30 sport=22 dport=44232 [ASSURED]
>>       (pid=11083) [ERROR] inject-add2: Device or resource busy
>
> This EBUSY seems to be always inject-add2 phase though.
>
> I've tried both conntrackd 1.0.1 and 1.4.3, both compiled against
> libnfnetlink-1.0.1; the behavior has been exactly the same.
>
> The hosts are running rather different kernels (3.10 from RHEL 7 (RS2) and
> 4.6.1-rt2 (RS1) respectively).

I can see them too, in NATed connections most of the time:


Jan 12 08:54:09 cf03 conntrack-tools[32717]: inject-upd1: File exists
Jan 12 08:54:09 cf03 conntrack-tools[32717]: tcp      6 120 TIME_WAIT
src=192.168.5.181 dst=31.13.65.1 sport=57419 dport=443 [ASSURED]
Jan 12 08:54:09 cf03 conntrack-tools[32717]: inject-upd1: File exists
Jan 12 08:54:09 cf03 conntrack-tools[32717]: tcp      6 10 CLOSE
src=192.168.5.181 dst=31.13.65.1 sport=57419 dport=443 [ASSURED]
Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-add2: File exists
Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 120 SYN_SENT
src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443 [UNREPLIED]
Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-upd1: File exists
Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 60 SYN_RECV
src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443
Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-upd1: File exists
Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 432000
ESTABLISHED src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443
[ASSURED]

this is linux 4.8.11 and conntrack-tools commit
5a51b045b369e3f8aa83cd32c14149158bd86546

Re: conntrackd: synchronization failures

[Jiri Kosina]

On Thu, 12 Jan 2017, Arturo Borrero Gonzalez wrote:

> I can see them too, in NATed connections most of the time:
> 
> Jan 12 08:54:09 cf03 conntrack-tools[32717]: inject-upd1: File exists
> Jan 12 08:54:09 cf03 conntrack-tools[32717]: tcp      6 120 TIME_WAIT
> src=192.168.5.181 dst=31.13.65.1 sport=57419 dport=443 [ASSURED]
> Jan 12 08:54:09 cf03 conntrack-tools[32717]: inject-upd1: File exists
> Jan 12 08:54:09 cf03 conntrack-tools[32717]: tcp      6 10 CLOSE
> src=192.168.5.181 dst=31.13.65.1 sport=57419 dport=443 [ASSURED]
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-add2: File exists
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 120 SYN_SENT
> src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443 [UNREPLIED]
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-upd1: File exists
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 60 SYN_RECV
> src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-upd1: File exists
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 432000
> ESTABLISHED src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443
> [ASSURED]

Do you also experience (either from inject-upd2 or inject-add2 phase) 
EBUSY ones?

I'm seeing quite a lot of entries such as

	(pid=9769) [ERROR] inject-add2: Device or resource busy
	        tcp      6 300 CLOSE src=10.33.37.4 dst=77.75.77.94 sport=42653 dport=443 [UNREPLIED]

I'm still trying to understand from the source what consequences this 
might have; any hint would be appreciated.

Thanks,

-- 
Jiri Kosina <jikos@kernel.org>
SUSE Labs

Re: conntrackd: synchronization failures

[Pablo Neira Ayuso]

On Fri, Jan 13, 2017 at 04:01:43PM +0100, Jiri Kosina wrote:
> On Thu, 12 Jan 2017, Arturo Borrero Gonzalez wrote:
> 
> > I can see them too, in NATed connections most of the time:
> > 
> > Jan 12 08:54:09 cf03 conntrack-tools[32717]: inject-upd1: File exists
> > Jan 12 08:54:09 cf03 conntrack-tools[32717]: tcp      6 120 TIME_WAIT
> > src=192.168.5.181 dst=31.13.65.1 sport=57419 dport=443 [ASSURED]
> > Jan 12 08:54:09 cf03 conntrack-tools[32717]: inject-upd1: File exists
> > Jan 12 08:54:09 cf03 conntrack-tools[32717]: tcp      6 10 CLOSE
> > src=192.168.5.181 dst=31.13.65.1 sport=57419 dport=443 [ASSURED]
> > Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-add2: File exists
> > Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 120 SYN_SENT
> > src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443 [UNREPLIED]
> > Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-upd1: File exists
> > Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 60 SYN_RECV
> > src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443
> > Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-upd1: File exists
> > Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 432000
> > ESTABLISHED src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443
> > [ASSURED]
> 
> Do you also experience (either from inject-upd2 or inject-add2 phase) 
> EBUSY ones?
> 
> I'm seeing quite a lot of entries such as
> 
> 	(pid=9769) [ERROR] inject-add2: Device or resource busy
> 	        tcp      6 300 CLOSE src=10.33.37.4 dst=77.75.77.94 sport=42653 dport=443 [UNREPLIED]
> 
> I'm still trying to understand from the source what consequences this 
> might have; any hint would be appreciated.

Some conntrack attributes can also be set up from NEW flows.

Most likely this entry already exists in the kernel, and conntrackd is
trying to update it.

Re: conntrackd: synchronization failures

[Pablo Neira Ayuso]

On Thu, Jan 12, 2017 at 08:58:32AM +0100, Arturo Borrero Gonzalez wrote:
> On 11 January 2017 at 22:57, Jiri Kosina <jikos@kernel.org> wrote:
> > On Wed, 11 Jan 2017, Jiri Kosina wrote:
> >
> >>       (pid=11083) [ERROR] inject-add2: File exists
> >
> > Sometimes this EEXIST is reported in inject-add1
> >
> >>               tcp      6 120 FIN_WAIT src=10.33.12.15 dst=116.31.116.30 sport=22 dport=44232 [ASSURED]
> >>       (pid=11083) [ERROR] inject-add2: Device or resource busy
> >
> > This EBUSY seems to be always inject-add2 phase though.
> >
> > I've tried both conntrackd 1.0.1 and 1.4.3, both compiled against
> > libnfnetlink-1.0.1; the behavior has been exactly the same.
> >
> > The hosts are running rather different kernels (3.10 from RHEL 7 (RS2) and
> > 4.6.1-rt2 (RS1) respectively).
> 
> I can see them too, in NATed connections most of the time:
> 
> 
> Jan 12 08:54:09 cf03 conntrack-tools[32717]: inject-upd1: File exists
> Jan 12 08:54:09 cf03 conntrack-tools[32717]: tcp      6 120 TIME_WAIT
> src=192.168.5.181 dst=31.13.65.1 sport=57419 dport=443 [ASSURED]
> Jan 12 08:54:09 cf03 conntrack-tools[32717]: inject-upd1: File exists
> Jan 12 08:54:09 cf03 conntrack-tools[32717]: tcp      6 10 CLOSE
> src=192.168.5.181 dst=31.13.65.1 sport=57419 dport=443 [ASSURED]
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-add2: File exists
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 120 SYN_SENT
> src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443 [UNREPLIED]
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-upd1: File exists
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 60 SYN_RECV
> src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: inject-upd1: File exists
> Jan 12 08:55:15 cf03 conntrack-tools[32717]: tcp      6 432000
> ESTABLISHED src=192.168.5.219 dst=216.58.211.202 sport=45121 dport=443
> [ASSURED]
> 
> this is linux 4.8.11 and conntrack-tools commit
> 5a51b045b369e3f8aa83cd32c14149158bd86546

Sorry I'm jumping late on this. Burden here has kept me away from
conntrackd issues.

Asymmetric packet route setups are a bit of hell on wheels since it is
prone to races. I said this many times before, and I know many people
ask for this setup. Flow based distribution fits much better with
stateful firewalls to achieve active-active setups. Main problem with
this scenario is that the sync message may lose race as it may get to
the other firewall later than reply packets, moreover, we cannot do
any smart trick to reduce the number of sync messages since every new
event need to be propagated to the other firewall.

What do

        cat /proc/sys/net/netfilter/nf_conntrack_tcp_loose
        cat /proc/sys/net/netfilter/nf_conntrack_tcp_be_liberal

say there? Here in my testbed this says:

        cat /proc/sys/net/netfilter/nf_conntrack_tcp_loose
        0
        cat /proc/sys/net/netfilter/nf_conntrack_tcp_be_liberal
        1

So TCP window tracking is disabled and we don't pick up connection
from the middle. If we allow connection pick from the middle, then
state synchronization is not useful, actually conntrackd may get there
late and try to add an entry (hence the EEXIST). The EBUSY case is
just like EEXIST, but it reports that that you're trying to update a
flow entry with stale information, so also likely lost race.

Are you also dropping invalid packets via?

        -A FORWARD -m state --state INVALID -j DROP

This just ensures that packets are dropped if flow state is not in
sync, so you force retransmissions if conntrackd loses race.

Can you also monitor netlink overrun via conntrackd -s? netlink
overrun is bad since this means the sync daemon cannot keep up with
the sync message pace, ie. we're losing sync events. That's also not
good.

Bottom line is: If you need an asymmetric packet route setup, better
consider running those routers as stateless firewalls, or do the
stateful firewalling before those edge routers, at a point where all
traffic (in both directions) is seen by the stateful firewall.
Stateful firewalls need to see traffic going in both directions, yes,
you can use conntrackd to workaround the fact that we will not see all
packets, but still prone to races.