[strongSwan] Problem with rekey collisions
andreas.braun at bagus.de
andreas.braun at bagus.de
Tue Jan 20 12:27:22 CET 2015
Dear strongSwan mailing list,
this is a hard one for me, but I hope you can help me a little bit. I have a
problem regarding rekey collisions with our IPsec connections. But first let
me introduce our setup to you:
We have four IPsec devices in different cities running the latest version of
IPFire (a Linux firewall distribution), which uses strongSwan 5.2.0 for
IPsec connections. All devices connect to each other. So every device has an
IPSec tunnel to the three other devices.
Now my problem is that tunnels between devices break every few days. The log
states that strongSwan detects a CHILD_REKEY collision, then it resolves the
collision, but no traffic is going through.
All tunnels are setup in the same way. Let's focus on our connection between
Essen and Frankfurt.
These are the connection settings from ipsec.conf:
version 2
conn %default
keyingtries=%forever
include /etc/ipsec.user.conf (which is empty)
conn VpnEssenFrankfurt
left=xxx.xxx.xxx.178
leftsubnet=192.168.241.0/24
leftfirewall=yes
lefthostaccess=yes
right=xxx.xxx.xxx.254
rightsubnet=10.2.34.0/24
leftid="xxx.xxx.xxx.178"
rightid="xxx.xxx.xxx.254"
ike=aes128-sha-modp2048,aes128-sha-modp1536,aes128-sha-modp1024
esp=aes128-sha1-modp2048,aes128-sha1-modp1536,aes128-sha1-modp1024
keyexchange=ikev2
ikelifetime=8h
keylife=1h
compress=yes
dpdaction=restart
dpddelay=120
dpdtimeout=30
authby=secret
auto=start
rekeymargin, rekeyfuzz are not set, so they should be at default values. I
have checked that rekeying happens about every 42 to 47 minutes, so I'd
guess randomization works.
Log entries from Essen when CHILD_REKEY collision happens:
----------------------------------------------------------
09:15:23 charon: 09[KNL] creating rekey job for ESP CHILD_SA with SPI
cb2b4672 and reqid {62}
09:15:23 charon: 09[IKE] establishing CHILD_SA VpnEssenFrankfurt{62}
09:15:23 charon: 09[IKE] establishing CHILD_SA VpnEssenFrankfurt{62}
09:15:24 charon: 09[ENC] generating CREATE_CHILD_SA request 8 [ N(REKEY_SA)
N(IPCOMP_SUP) SA No KE TSi TSr ]
09:15:24 charon: 09[NET] sending packet: from xxx.xxx.xxx.178[4500] to
xxx.xxx.xxx.254[4500] (684 bytes)
09:15:24 charon: 03[NET] received packet: from xxx.xxx.xxx.254[4500] to
xxx.xxx.xxx.178[4500] (684 bytes)
09:15:24 charon: 03[ENC] parsed CREATE_CHILD_SA request 4 [ N(REKEY_SA)
N(IPCOMP_SUP) SA No KE TSi TSr ]
09:15:25 charon: 03[IKE] CHILD_SA VpnEssenFrankfurt{62} established with
SPIs cdebd4fd_i c11a7965_o and TS 192.168.241.0/24 === 10.2.34.0/24
09:15:25 charon: 03[IKE] CHILD_SA VpnEssenFrankfurt{62} established with
SPIs cdebd4fd_i c11a7965_o and TS 192.168.241.0/24 === 10.2.34.0/24
09:15:25 charon: 03[IKE] detected CHILD_REKEY collision with CHILD_REKEY
09:15:25 charon: 03[ENC] generating CREATE_CHILD_SA response 4 [
N(IPCOMP_SUP) SA No KE TSi TSr ]
09:15:25 charon: 03[NET] sending packet: from xxx.xxx.xxx.178[4500] to
xxx.xxx.xxx.254[4500] (476 bytes)
09:15:25 charon: 13[NET] received packet: from xxx.xxx.xxx.254[4500] to
xxx.xxx.xxx.178[4500] (476 bytes)
09:15:25 charon: 13[ENC] parsed CREATE_CHILD_SA response 8 [ N(IPCOMP_SUP)
SA No KE TSi TSr ]
09:15:25 charon: 13[IKE] CHILD_SA VpnEssenFrankfurt{62} established with
SPIs ceae6ae6_i c2cd43e9_o and TS 192.168.241.0/24 === 10.2.34.0/24
09:15:25 charon: 13[IKE] CHILD_SA VpnEssenFrankfurt{62} established with
SPIs ceae6ae6_i c2cd43e9_o and TS 192.168.241.0/24 === 10.2.34.0/24
09:15:25 charon: 13[IKE] CHILD_SA rekey collision lost, deleting rekeyed
child
09:15:25 charon: 13[IKE] closing CHILD_SA VpnEssenFrankfurt{62} with SPIs
ceae6ae6_i (0 bytes) c2cd43e9_o (0 bytes) and TS 192.168.241.0/24 ===
10.2.34.0/24
09:15:25 charon: 13[IKE] closing CHILD_SA VpnEssenFrankfurt{62} with SPIs
ceae6ae6_i (0 bytes) c2cd43e9_o (0 bytes) and TS 192.168.241.0/24 ===
10.2.34.0/24
09:15:25 charon: 13[IKE] sending DELETE for ESP CHILD_SA with SPI ceae6ae6
09:15:25 charon: 13[ENC] generating INFORMATIONAL request 9 [ D ]
09:15:25 charon: 13[NET] sending packet: from xxx.xxx.xxx.178[4500] to
xxx.xxx.xxx.254[4500] (76 bytes)
09:15:25 charon: 05[NET] received packet: from xxx.xxx.xxx.254[4500] to
xxx.xxx.xxx.178[4500] (76 bytes)
09:15:25 charon: 05[ENC] parsed INFORMATIONAL request 5 [ D ]
09:15:25 charon: 05[IKE] received DELETE for ESP CHILD_SA with SPI cb2b4672
09:15:25 charon: 05[IKE] closing CHILD_SA VpnEssenFrankfurt{62} with SPIs
c6459ba2_i (1174847 bytes) cb2b4672_o (638727 bytes) and TS 192.168.241.0/24
=== 10.2.34.0/24
09:15:25 charon: 05[IKE] closing CHILD_SA VpnEssenFrankfurt{62} with SPIs
c6459ba2_i (1174847 bytes) cb2b4672_o (638727 bytes) and TS 192.168.241.0/24
=== 10.2.34.0/24
09:15:25 charon: 05[IKE] sending DELETE for ESP CHILD_SA with SPI c6459ba2
09:15:25 charon: 05[IKE] CHILD_SA closed
09:15:25 charon: 05[IKE] detected CHILD_REKEY collision with CHILD_DELETE
09:15:25 charon: 05[ENC] generating INFORMATIONAL response 5 [ D ]
09:15:25 charon: 05[NET] sending packet: from xxx.xxx.xxx.178[4500] to
xxx.xxx.xxx.254[4500] (76 bytes)
09:15:25 charon: 16[NET] received packet: from xxx.xxx.xxx.254[4500] to
xxx.xxx.xxx.178[4500] (76 bytes)
09:15:25 charon: 16[ENC] parsed INFORMATIONAL response 9 [ D ]
09:15:25 charon: 16[IKE] received DELETE for ESP CHILD_SA with SPI c2cd43e9
09:15:25 charon: 16[IKE] CHILD_SA closed
Log entries from Frankfurt when CHILD_REKEY collision happens:
--------------------------------------------------------------
09:15:24 charon: 08[KNL] creating rekey job for ESP CHILD_SA with SPI
c6459ba2 and reqid {96}
09:15:24 charon: 08[IKE] queueing CHILD_REKEY task
09:15:24 charon: 08[IKE] queueing CHILD_REKEY task
09:15:24 charon: 08[IKE] activating new tasks
09:15:24 charon: 08[IKE] activating new tasks
09:15:24 charon: 08[IKE] activating CHILD_REKEY task
09:15:24 charon: 08[IKE] activating CHILD_REKEY task
09:15:24 charon: 08[IKE] establishing CHILD_SA VpnFrankfurtEssen{96}
09:15:24 charon: 08[IKE] establishing CHILD_SA VpnFrankfurtEssen{96}
09:15:24 charon: 08[ENC] generating CREATE_CHILD_SA request 4 [ N(REKEY_SA)
N(IPCOMP_SUP) SA No KE TSi TSr ]
09:15:24 charon: 08[NET] sending packet: from xxx.xxx.xxx.254[4500] to
xxx.xxx.xxx.178[4500] (684 bytes)
09:15:24 charon: 14[NET] received packet: from xxx.xxx.xxx.178[4500] to
xxx.xxx.xxx.254[4500] (684 bytes)
09:15:24 charon: 14[ENC] parsed CREATE_CHILD_SA request 8 [ N(REKEY_SA)
N(IPCOMP_SUP) SA No KE TSi TSr ]
09:15:25 charon: 14[IKE] CHILD_SA VpnFrankfurtEssen{96} established with
SPIs c2cd43e9_i ceae6ae6_o and TS 10.2.34.0/24 === 192.168.241.0/24
09:15:25 charon: 14[IKE] CHILD_SA VpnFrankfurtEssen{96} established with
SPIs c2cd43e9_i ceae6ae6_o and TS 10.2.34.0/24 === 192.168.241.0/24
09:15:25 charon: 14[IKE] detected CHILD_REKEY collision with CHILD_REKEY
09:15:25 charon: 14[IKE] detected CHILD_REKEY collision with CHILD_REKEY
09:15:25 charon: 14[ENC] generating CREATE_CHILD_SA response 8 [
N(IPCOMP_SUP) SA No KE TSi TSr ]
09:15:25 charon: 14[NET] sending packet: from xxx.xxx.xxx.254[4500] to
xxx.xxx.xxx.178[4500] (476 bytes)
09:15:25 charon: 13[NET] received packet: from xxx.xxx.xxx.178[4500] to
xxx.xxx.xxx.254[4500] (476 bytes)
09:15:25 charon: 13[ENC] parsed CREATE_CHILD_SA response 4 [ N(IPCOMP_SUP)
SA No KE TSi TSr ]
09:15:25 charon: 13[IKE] received IPCOMP_SUPPORTED notify
09:15:25 charon: 13[IKE] received IPCOMP_SUPPORTED notify
09:15:25 charon: 13[IKE] CHILD_SA VpnFrankfurtEssen{96} established with
SPIs c11a7965_i cdebd4fd_o and TS 10.2.34.0/24 === 192.168.241.0/24
09:15:25 charon: 13[IKE] CHILD_SA VpnFrankfurtEssen{96} established with
SPIs c11a7965_i cdebd4fd_o and TS 10.2.34.0/24 === 192.168.241.0/24
09:15:25 charon: 13[IKE] CHILD_SA rekey collision won, deleting old child
09:15:25 charon: 13[IKE] CHILD_SA rekey collision won, deleting old child
09:15:25 charon: 13[IKE] reinitiating already active tasks
09:15:25 charon: 13[IKE] reinitiating already active tasks
09:15:25 charon: 13[IKE] CHILD_REKEY task
09:15:25 charon: 13[IKE] CHILD_REKEY task
09:15:25 charon: 13[IKE] closing CHILD_SA VpnFrankfurtEssen{96} with SPIs
cb2b4672_i (638727 bytes) c6459ba2_o (1180599 bytes) and TS 10.2.34.0/24 ===
192.168.241.0/24
09:15:25 charon: 13[IKE] closing CHILD_SA VpnFrankfurtEssen{96} with SPIs
cb2b4672_i (638727 bytes) c6459ba2_o (1180599 bytes) and TS 10.2.34.0/24 ===
192.168.241.0/24
09:15:25 charon: 13[IKE] sending DELETE for ESP CHILD_SA with SPI cb2b4672
09:15:25 charon: 13[IKE] sending DELETE for ESP CHILD_SA with SPI cb2b4672
09:15:25 charon: 13[ENC] generating INFORMATIONAL request 5 [ D ]
09:15:25 charon: 13[NET] sending packet: from xxx.xxx.xxx.254[4500] to
xxx.xxx.xxx.178[4500] (76 bytes)
09:15:25 charon: 01[NET] received packet: from xxx.xxx.xxx.178[4500] to
xxx.xxx.xxx.254[4500] (76 bytes)
09:15:25 charon: 01[ENC] parsed INFORMATIONAL request 9 [ D ]
09:15:25 charon: 01[IKE] received DELETE for ESP CHILD_SA with SPI ceae6ae6
09:15:25 charon: 01[IKE] received DELETE for ESP CHILD_SA with SPI ceae6ae6
09:15:25 charon: 01[IKE] closing CHILD_SA VpnFrankfurtEssen{96} with SPIs
c2cd43e9_i (0 bytes) ceae6ae6_o (0 bytes) and TS 10.2.34.0/24 ===
192.168.241.0/24
09:15:25 charon: 01[IKE] closing CHILD_SA VpnFrankfurtEssen{96} with SPIs
c2cd43e9_i (0 bytes) ceae6ae6_o (0 bytes) and TS 10.2.34.0/24 ===
192.168.241.0/24
09:15:25 charon: 01[IKE] sending DELETE for ESP CHILD_SA with SPI c2cd43e9
09:15:25 charon: 01[IKE] sending DELETE for ESP CHILD_SA with SPI c2cd43e9
09:15:25 charon: 01[IKE] CHILD_SA closed
09:15:25 charon: 01[IKE] CHILD_SA closed
09:15:26 charon: 01[ENC] generating INFORMATIONAL response 9 [ D ]
09:15:26 charon: 01[NET] sending packet: from xxx.xxx.xxx.254[4500] to
xxx.xxx.xxx.178[4500] (76 bytes)
09:15:26 charon: 05[NET] received packet: from xxx.xxx.xxx.178[4500] to
xxx.xxx.xxx.254[4500] (76 bytes)
09:15:26 charon: 05[ENC] parsed INFORMATIONAL response 5 [ D ]
09:15:26 charon: 05[IKE] received DELETE for ESP CHILD_SA with SPI c6459ba2
09:15:26 charon: 05[IKE] received DELETE for ESP CHILD_SA with SPI c6459ba2
09:15:26 charon: 05[IKE] CHILD_SA closed
09:15:26 charon: 05[IKE] CHILD_SA closed
09:15:26 charon: 05[IKE] activating new tasks
09:15:26 charon: 05[IKE] activating new tasks
09:15:26 charon: 05[IKE] nothing to initiate
09:15:26 charon: 05[IKE] nothing to initiate
Only after waiting a few hours or if we restart the connection, the traffic
will flow again:
----------------------------------------------------------------------------
----------------
12:08:35 charon: 07[CFG] received stroke: terminate 'VpnEssenFrankfurt'
12:08:35 charon: 09[IKE] deleting IKE_SA VpnEssenFrankfurt[106] between
xxx.xxx.xxx.178[xxx.xxx.xxx.178]...xxx.xxx.xxx.254[xxx.xxx.xxx.254]
12:08:35 charon: 09[IKE] deleting IKE_SA VpnEssenFrankfurt[106] between
xxx.xxx.xxx.178[xxx.xxx.xxx.178]...xxx.xxx.xxx.254[xxx.xxx.xxx.254]
12:08:35 charon: 09[IKE] sending DELETE for IKE_SA VpnEssenFrankfurt[106]
12:08:35 charon: 09[ENC] generating INFORMATIONAL request 14 [ D ]
12:08:35 charon: 09[NET] sending packet: from xxx.xxx.xxx.178[4500] to
xxx.xxx.xxx.254[4500] (76 bytes)
12:08:35 charon: 01[NET] received packet: from xxx.xxx.xxx.254[4500] to
xxx.xxx.xxx.178[4500] (76 bytes)
12:08:35 charon: 01[ENC] parsed INFORMATIONAL response 14 [ ]
12:08:35 charon: 01[IKE] IKE_SA deleted
12:08:35 charon: 01[IKE] IKE_SA deleted
12:08:35 charon: 01[CHD] updown: iptables: No chain/target/match by that
name.
12:08:35 charon: 01[CHD] updown: iptables: Bad rule (does a matching rule
exist in that chain?).
12:08:35 charon: 01[CHD] updown: iptables: Bad rule (does a matching rule
exist in that chain?).
12:08:35 charon: 01[CHD] updown: iptables: No chain/target/match by that
name.
12:08:35 charon: 01[CHD] updown: iptables: Bad rule (does a matching rule
exist in that chain?).
12:08:35 charon: 01[CHD] updown: iptables: Bad rule (does a matching rule
exist in that chain?).
12:08:35 charon: 01[CHD] updown: iptables: No chain/target/match by that
name.
12:08:35 charon: 16[CFG] rereading secrets
12:08:35 charon: 16[CFG] loading secrets from '/etc/ipsec.secrets'
12:08:35 charon: 16[CFG] loading secrets from '/etc/ipsec.user.secrets'
Then I created a test setup using VMs with the same software. To force rekey
collisions I changed the following settings:
keylife=3m
rekeymargin=1m
rekeyfuzz=0%
I noticed that after a rekey collision, some iptables rules were gone. I
still have to verify this in the production system.
Before rekey collision:
-----------------------
Chain IPSECFORWARD (1 references)
target prot opt source destination
RETURN all -- 10.1.34.0/24 10.2.34.0/24 policy match
dir in pol ipsec reqid 1 proto 50
MARK all -- 10.2.34.0/24 10.1.34.0/24 policy match
dir out pol ipsec reqid 1 proto 50 MARK set 0x32
Chain IPSECINPUT (1 references)
target prot opt source destination
ACCEPT esp -- 10.1.100.178 10.1.100.254
ACCEPT ah -- 10.1.100.178 10.1.100.254
ACCEPT 4 -- 10.1.100.178 10.1.100.254
ACCEPT 4 -- 10.1.100.178 10.1.100.254 policy match
dir in pol ipsec reqid 1 proto 50
RETURN all -- 10.1.34.0/24 10.2.34.0/24 policy match
dir in pol ipsec reqid 1 proto 50
ACCEPT udp -- 0.0.0.0/0 0.0.0.0/0 udp dpt:500
ACCEPT udp -- 0.0.0.0/0 0.0.0.0/0 udp dpt:4500
ACCEPT udp -- 0.0.0.0/0 0.0.0.0/0 udp dpt:500
ACCEPT udp -- 0.0.0.0/0 0.0.0.0/0 udp dpt:4500
Chain IPSECOUTPUT (1 references)
target prot opt source destination
MARK all -- 10.2.34.0/24 10.1.34.0/24 policy match
dir out pol ipsec reqid 1 proto 50 MARK set 0x32
After rekey collision:
----------------------
Chain IPSECFORWARD (1 references)
target prot opt source destination
Chain IPSECINPUT (1 references)
target prot opt source destination
ACCEPT udp -- 0.0.0.0/0 0.0.0.0/0 udp dpt:500
ACCEPT udp -- 0.0.0.0/0 0.0.0.0/0 udp dpt:4500
ACCEPT udp -- 0.0.0.0/0 0.0.0.0/0 udp dpt:500
ACCEPT udp -- 0.0.0.0/0 0.0.0.0/0 udp dpt:4500
Chain IPSECOUTPUT (1 references)
target prot opt source destination
My questions are:
1.) Is there any way to check wether rekey time randomization really works
as it should?
2.) Could you tell me why I am getting CHILD_REKEY collisions every few
days? Is that to be expected?
3.) Any idea why the iptables rules get changed after rekey collision?
If you need more information, please tell me. I am glad for any help.
Kind regards
Andreas Braun
Systemadministration
____________________________________________________________________
BAGUS - Gesellschaft für Unternehmensberatung und Systemlösungen mbH
Dorotheenstr. 3 / 45130 Essen
E-Mail: andreas.braun at bagus.de / www.bagus-gruppe.de
HRB Essen 12437 / GF Günter Baginski & Olaf Michels
____________________________________________________________________
BAGUS Unternehmensgruppe
More information about the Users
mailing list