Hi Martin I think we've figured out what is happening...
We have an updown script which flushes and recreates the firewall rules whenever the interface is started but the forward rules are created by strongswan using leftfirewall=yes. It seems that strongswan restarts the interface under some circumstances (e.g. after a rekey collision) which causes the forward rules to be removed. Aug 5 13:39:19 zsitegate-00 charon: 13[IKE] detected CHILD_REKEY collision with CHILD_DELETE Aug 5 13:39:19 zsitegate-00 charon: 13[ENC] generating INFORMATIONAL response 3 [ D ] Aug 5 13:39:19 zsitegate-00 charon: 13[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (76 bytes) Aug 5 13:39:19 zsitegate-00 charon: 04[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (76 bytes) Aug 5 13:39:19 zsitegate-00 charon: 04[ENC] parsed INFORMATIONAL response 3 [ D ] Aug 5 13:39:19 zsitegate-00 charon: 04[IKE] received DELETE for ESP CHILD_SA with SPI c878e1b3 Aug 5 13:39:19 zsitegate-00 charon: 04[IKE] CHILD_SA closed Aug 5 13:39:19 zsitegate-00 vpn: - CN=intersite-customer-0000-0003, OU=HAP Customers 10.0.20.128/25 == 192.168.100.224 -- 10.0.3.177 == 10.0.3.128/25 Aug 5 13:39:23 zsitegate-00 charon: 03[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (76 bytes) Aug 5 13:39:23 zsitegate-00 charon: 03[ENC] parsed INFORMATIONAL request 3 [ D ] Aug 5 13:39:23 zsitegate-00 charon: 03[IKE] received retransmit of request with ID 3, retransmitting response Aug 5 13:39:23 zsitegate-00 charon: 03[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (76 bytes) Aug 5 13:40:46 zsitegate-00 charon: 03[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (76 bytes) Aug 5 13:40:46 zsitegate-00 charon: 03[ENC] parsed INFORMATIONAL request 4 [ D ] Aug 5 13:40:46 zsitegate-00 charon: 03[IKE] received DELETE for IKE_SA 0000-0003-private-to-0000-0014-private[1] Aug 5 13:40:46 zsitegate-00 charon: 03[IKE] deleting IKE_SA 0000-0003-private-to-0000-0014-private[1] between 10.0.3.177[CN=intersite-customer-0000-0003, OU=HAP Customers]...192.168.100.224[CN=intersite-customer-0000-0003, OU=HAP Customers] Aug 5 13:40:46 zsitegate-00 charon: 03[IKE] IKE_SA deleted Aug 5 13:40:46 zsitegate-00 charon: 03[CHD] updown: iptables: Bad rule (does a matching rule exist in that chain?). Aug 5 13:40:46 zsitegate-00 charon: 03[CHD] updown: iptables: Bad rule (does a matching rule exist in that chain?). I guess we will change the rule to leftfirewall=false and set the forwarding rule ourselves. Thanks very much for your assistance Steve Lee Senior Architect Phone: +44 (0)7474 647674 www.zynstra.com Zynstra is a private limited company registered in England and Wales (registered number 07864369). Our registered office is 5 New Street Square, London, EC4A 3TW and our headquarters are at Bath Ventures, Broad Quay, Bath, BA1 1UD. ________________________________________ From: Steve Lee Sent: 05 August 2014 15:32 To: Martin Willi Cc: [email protected] Subject: RE: [strongSwan] Rekey Collisions Hi Martin I reduced the parameters still further and got a collision quite quickly. WIth a single tunnel I didnt see the mismatch between SPIs on the 2 sides but traffic definitely stopped going through the tunnel. ikelifetime=9m keylife=3m rekeymargin=1m rekeyfuzz=0% keyingtries=1 The complete logs from ipsec start to ipsec stop (about 10 mins) are below but I couldn't see anything wrong and couldn't see any output from the patch you sent. Interesting though that there were 2 collisions in the same second... Aug 5 13:39:19 zsitegate-00 charon: 14[IKE] detected CHILD_REKEY collision with CHILD_REKEY Aug 5 13:39:19 zsitegate-00 charon: 15[IKE] CHILD_SA rekey collision lost, deleting rekeyed child Aug 5 13:39:19 zsitegate-00 charon: 13[IKE] detected CHILD_REKEY collision with CHILD_DELETE SIte 1 Log Aug 5 13:35:12 zsitegate-00 charon: 00[DMN] Starting IKE charon daemon (strongSwan 5.1.1, Linux 3.8.0-30-raring-zdomu, x86_64) Aug 5 13:35:12 zsitegate-00 charon: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts' Aug 5 13:35:12 zsitegate-00 charon: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts' Aug 5 13:35:12 zsitegate-00 charon: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts' Aug 5 13:35:12 zsitegate-00 charon: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts' Aug 5 13:35:12 zsitegate-00 charon: 00[CFG] loading crls from '/etc/ipsec.d/crls' Aug 5 13:35:12 zsitegate-00 charon: 00[CFG] loading secrets from '/etc/ipsec.secrets' Aug 5 13:35:12 zsitegate-00 charon: 00[CFG] loaded RSA private key from '/etc/certificates/.intersite.myx509.key' Aug 5 13:35:12 zsitegate-00 charon: 00[LIB] loaded plugins: charon aes des rc2 sha1 sha2 md5 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl fips-prf gmp xcbc cmac hmac attr kernel-netlink resolve socket-default stroke updown xauth-generic Aug 5 13:35:12 zsitegate-00 charon: 00[LIB] unable to load 3 plugin features (3 due to unmet dependencies) Aug 5 13:35:12 zsitegate-00 charon: 00[JOB] spawning 16 worker threads Aug 5 13:35:12 zsitegate-00 charon: 10[CFG] received stroke: add ca 'ca1' Aug 5 13:35:12 zsitegate-00 charon: 10[CFG] loaded ca certificate "dnQualifier=HAP CA, OU=certificates, O=Zynstra Ltd, L=BATH, C=GB" from '/etc/certificates/ca/zynstra.pem' Aug 5 13:35:12 zsitegate-00 charon: 10[CFG] added ca 'ca1' Aug 5 13:35:12 zsitegate-00 charon: 05[CFG] received stroke: add connection '0000-0003-private-to-0000-0014-private' Aug 5 13:35:12 zsitegate-00 charon: 05[CFG] loaded certificate "CN=intersite-customer-0000-0003, OU=HAP Customers" from '/etc/certificates/.intersite.myx509.crt' Aug 5 13:35:12 zsitegate-00 charon: 05[CFG] added configuration '0000-0003-private-to-0000-0014-private' Aug 5 13:35:12 zsitegate-00 charon: 13[CFG] received stroke: route '0000-0003-private-to-0000-0014-private' Aug 5 13:35:19 zsitegate-00 charon: 16[NET] received packet: from 192.168.100.224[500] to 10.0.3.177[500] (924 bytes) Aug 5 13:35:19 zsitegate-00 charon: 16[ENC] parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ] Aug 5 13:35:19 zsitegate-00 charon: 16[IKE] 192.168.100.224 is initiating an IKE_SA Aug 5 13:35:19 zsitegate-00 charon: 16[IKE] local host is behind NAT, sending keep alives Aug 5 13:35:19 zsitegate-00 charon: 16[IKE] remote host is behind NAT Aug 5 13:35:19 zsitegate-00 charon: 16[IKE] sending cert request for "dnQualifier=HAP CA, OU=certificates, O=Zynstra Ltd, L=BATH, C=GB" Aug 5 13:35:19 zsitegate-00 charon: 16[ENC] generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ] Aug 5 13:35:19 zsitegate-00 charon: 16[NET] sending packet: from 10.0.3.177[500] to 192.168.100.224[500] (465 bytes) Aug 5 13:35:19 zsitegate-00 charon: 04[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (1932 bytes) Aug 5 13:35:19 zsitegate-00 charon: 04[ENC] parsed IKE_AUTH request 1 [ IDi CERT CERTREQ IDr AUTH SA TSi TSr N(MOBIKE_SUP) N(ADD_6_ADDR) N(MULT_AUTH) N(EAP_ONLY) ] Aug 5 13:35:19 zsitegate-00 charon: 04[IKE] received cert request for "dnQualifier=HAP CA, OU=certificates, O=Zynstra Ltd, L=BATH, C=GB" Aug 5 13:35:19 zsitegate-00 charon: 04[IKE] received end entity cert "CN=intersite-customer-0000-0003, OU=HAP Customers" Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] looking for peer configs matching 10.0.3.177[CN=intersite-customer-0000-0003, OU=HAP Customers]...192.168.100.224[CN=intersite-customer-0000-0003, OU=HAP Customers] Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] selected peer config '0000-0003-private-to-0000-0014-private' Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] using trusted intermediate ca certificate "dnQualifier=HAP CA, OU=certificates, O=Zynstra Ltd, L=BATH, C=GB" Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] checking certificate status of "CN=intersite-customer-0000-0003, OU=HAP Customers" Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] requesting ocsp status from 'http://localhost:8080/ejbca/publicweb/status/ocsp' ... Aug 5 13:35:19 zsitegate-00 charon: 04[LIB] unable to fetch from http://localhost:8080/ejbca/publicweb/status/ocsp, no capable fetcher found Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] ocsp request to http://localhost:8080/ejbca/publicweb/status/ocsp failed Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] ocsp check failed, fallback to crl Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] fetching crl from 'http://localhost:8080/ejbca/publicweb/webdist/certdist?cmd=crl&issuer=DN=HAP%20CA,OU=certificates,O=Zynstra%20Ltd,L=BATH,C=GB' ... Aug 5 13:35:19 zsitegate-00 charon: 04[LIB] unable to fetch from http://localhost:8080/ejbca/publicweb/webdist/certdist?cmd=crl&issuer=DN=HAP%20CA,OU=certificates,O=Zynstra%20Ltd,L=BATH,C=GB, no capable fetcher found Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] crl fetching failed Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] certificate status is not available Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] reached self-signed root ca with a path length of 0 Aug 5 13:35:19 zsitegate-00 charon: 04[CFG] using trusted certificate "CN=intersite-customer-0000-0003, OU=HAP Customers" Aug 5 13:35:19 zsitegate-00 charon: 04[IKE] aut thentication of 'CN=intersite-customer-0000-0003, OU=HAP Customers' with RSA signature successful Aug 5 13:35:19 zsitegate-00 charon: 04[IKE] peer supports MOBIKE Aug 5 13:35:19 zsitegate-00 charon: 04[IKE] authentication of 'CN=intersite-customer-0000-0003, OU=HAP Customers' (myself) with RSA signature successful Aug 5 13:35:19 zsitegate-00 charon: 04[IKE] IKE_SA 0000-0003-private-to-0000-0014-private[1] established between 10.0.3.177[CN=intersite-customer-0000-0003, OU=HAP Customers]...192.168.100.224[CN=intersite-customer-0000-0003, OU=HAP Customers] Aug 5 13:35:19 zsitegate-00 charon: 04[IKE] scheduling rekeying in 480s Aug 5 13:35:19 zsitegate-00 charon: 04[IKE] maximum IKE_SA lifetime 540s Aug 5 13:35:19 zsitegate-00 charon: 04[IKE] sending end entity cert "CN=intersite-customer-0000-0003, OU=HAP Customers" Aug 5 13:35:19 zsitegate-00 charon: 04[IKE] CHILD_SA 0000-0003-private-to-0000-0014-private{1} established with SPIs c7cca7a5_i cf1ae00e_o and TS 10.0.3.128/25 === 10.0.20.128/25 Aug 5 13:35:19 zsitegate-00 vpn: + CN=intersite-customer-0000-0003, OU=HAP Customers 10.0.20.128/25 == 192.168.100.224 -- 10.0.3.177 == 10.0.3.128/25 Aug 5 13:35:19 zsitegate-00 charon: 04[ENC] generating IKE_AUTH response 1 [ IDr CERT AUTH SA TSi TSr N(MOBIKE_SUP) N(ADD_6_ADDR) ] Aug 5 13:35:19 zsitegate-00 charon: 04[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (1644 bytes) Aug 5 13:37:19 zsitegate-00 charon: 04[KNL] creating rekey job for ESP CHILD_SA with SPI c7cca7a5 and reqid {1} Aug 5 13:37:19 zsitegate-00 charon: 04[IKE] establishing CHILD_SA 0000-0003-private-to-0000-0014-private{1} Aug 5 13:37:19 zsitegate-00 charon: 04[ENC] generating CREATE_CHILD_SA request 0 [ N(REKEY_SA) SA No TSi TSr ] Aug 5 13:37:19 zsitegate-00 charon: 04[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (348 bytes) Aug 5 13:37:19 zsitegate-00 charon: 03[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (204 bytes) Aug 5 13:37:19 zsitegate-00 charon: 03[ENC] parsed CREATE_CHILD_SA response 0 [ SA No TSi TSr ] Aug 5 13:37:19 zsitegate-00 charon: 03[IKE] CHILD_SA 0000-0003-private-to-0000-0014-private{1} established with SPIs c6dc909b_i c021887d_o and TS 10.0.3.128/25 === 10.0.20.128/25 Aug 5 13:37:19 zsitegate-00 charon: 03[IKE] closing CHILD_SA 0000-0003-private-to-0000-0014-private{1} with SPIs c7cca7a5_i (5254 bytes) cf1ae00e_o (7022 bytes) and TS 10.0.3.128/25 === 10.0.20.128/25 Aug 5 13:37:19 zsitegate-00 charon: 03[IKE] sending DELETE for ESP CHILD_SA with SPI c7cca7a5 Aug 5 13:37:19 zsitegate-00 charon: 03[ENC] generating INFORMATIONAL request 1 [ D ] Aug 5 13:37:19 zsitegate-00 charon: 03[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (76 bytes) Aug 5 13:37:19 zsitegate-00 charon: 16[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (76 bytes) Aug 5 13:37:19 zsitegate-00 charon: 16[ENC] parsed INFORMATIONAL response 1 [ D ] Aug 5 13:37:19 zsitegate-00 charon: 16[IKE] received DELETE for ESP CHILD_SA with SPI cf1ae00e Aug 5 13:37:19 zsitegate-00 charon: 16[IKE] CHILD_SA closed Aug 5 13:38:36 zsitegate-00 charon: 05[IKE] sending keep alive to 192.168.100.224[4500] Aug 5 13:39:19 zsitegate-00 charon: 10[KNL] creating rekey job for ESP CHILD_SA with SPI c6dc909b and reqid {1} Aug 5 13:39:19 zsitegate-00 charon: 10[IKE] establishing CHILD_SA 0000-0003-private-to-0000-0014-private{1} Aug 5 13:39:19 zsitegate-00 charon: 10[ENC] generating CREATE_CHILD_SA request 2 [ N(REKEY_SA) SA No TSi TSr ] Aug 5 13:39:19 zsitegate-00 charon: 10[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (348 bytes) Aug 5 13:39:19 zsitegate-00 charon: 14[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (348 bytes) Aug 5 13:39:19 zsitegate-00 charon: 14[ENC] parsed CREATE_CHILD_SA request 2 [ N(REKEY_SA) SA No TSi TSr ] Aug 5 13:39:19 zsitegate-00 charon: 14[IKE] CHILD_SA 0000-0003-private-to-0000-0014-private{1} established with SPIs c2719bec_i cee3eb14_o and TS 10.0.3.128/25 === 10.0.20.128/25 Aug 5 13:39:19 zsitegate-00 charon: 14[IKE] detected CHILD_REKEY collision with CHILD_REKEY Aug 5 13:39:19 zsitegate-00 charon: 14[ENC] generating CREATE_CHILD_SA response 2 [ SA No TSi TSr ] Aug 5 13:39:19 zsitegate-00 charon: 14[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (204 bytes) Aug 5 13:39:19 zsitegate-00 charon: 15[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (204 bytes) Aug 5 13:39:19 zsitegate-00 charon: 15[ENC] parsed CREATE_CHILD_SA response 2 [ SA No TSi TSr ] Aug 5 13:39:19 zsitegate-00 charon: 15[IKE] CHILD_SA 0000-0003-private-to-0000-0014-private{1} established with SPIs cc63239f_i c878e1b3_o and TS 10.0.3.128/25 === 10.0.20.128/25 Aug 5 13:39:19 zsitegate-00 charon: 15[IKE] CHILD_SA rekey collision lost, deleting rekeyed child Aug 5 13:39:19 zsitegate-00 charon: 15[IKE] closing CHILD_SA 0000-0003-private-to-0000-0014-private{1} with SPIs cc63239f_i (0 bytes) c878e1b3_o (0 bytes) and TS 10.0.3.128/25 === 10.0.20.128/25 Aug 5 13:39:19 zsitegate-00 charon: 15[IKE] sending DELETE for ESP CHILD_SA with SPI cc63239f Aug 5 13:39:19 zsitegate-00 charon: 15[ENC] generating INFORMATIONAL request 3 [ D ] Aug 5 13:39:19 zsitegate-00 charon: 15[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (76 bytes) Aug 5 13:39:19 zsitegate-00 charon: 13[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (76 bytes) Aug 5 13:39:19 zsitegate-00 charon: 13[ENC] parsed INFORMATIONAL request 3 [ D ] Aug 5 13:39:19 zsitegate-00 charon: 13[IKE] received DELETE for ESP CHILD_SA with SPI c021887d Aug 5 13:39:19 zsitegate-00 charon: 13[IKE] closing CHILD_SA 0000-0003-private-to-0000-0014-private{1} with SPIs c6dc909b_i (163224 bytes) c021887d_o (73363 bytes) and TS 10.0.3.128/25 === 10.0.20.128/25 Aug 5 13:39:19 zsitegate-00 charon: 13[IKE] sending DELETE for ESP CHILD_SA with SPI c6dc909b Aug 5 13:39:19 zsitegate-00 charon: 13[IKE] CHILD_SA closed Aug 5 13:39:19 zsitegate-00 charon: 13[IKE] detected CHILD_REKEY collision with CHILD_DELETE Aug 5 13:39:19 zsitegate-00 charon: 13[ENC] generating INFORMATIONAL response 3 [ D ] Aug 5 13:39:19 zsitegate-00 charon: 13[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (76 bytes) Aug 5 13:39:19 zsitegate-00 charon: 04[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (76 bytes) Aug 5 13:39:19 zsitegate-00 charon: 04[ENC] parsed INFORMATIONAL response 3 [ D ] Aug 5 13:39:19 zsitegate-00 charon: 04[IKE] received DELETE for ESP CHILD_SA with SPI c878e1b3 Aug 5 13:39:19 zsitegate-00 charon: 04[IKE] CHILD_SA closed Aug 5 13:39:19 zsitegate-00 vpn: - CN=intersite-customer-0000-0003, OU=HAP Customers 10.0.20.128/25 == 192.168.100.224 -- 10.0.3.177 == 10.0.3.128/25 Aug 5 13:39:23 zsitegate-00 charon: 03[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (76 bytes) Aug 5 13:39:23 zsitegate-00 charon: 03[ENC] parsed INFORMATIONAL request 3 [ D ] Aug 5 13:39:23 zsitegate-00 charon: 03[IKE] received retransmit of request with ID 3, retransmitting response Aug 5 13:39:23 zsitegate-00 charon: 03[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (76 bytes) Aug 5 13:40:46 zsitegate-00 charon: 03[NET] received packet: from 192.168.100.224[4500] to 10.0.3.177[4500] (76 bytes) Aug 5 13:40:46 zsitegate-00 charon: 03[ENC] parsed INFORMATIONAL request 4 [ D ] Aug 5 13:40:46 zsitegate-00 charon: 03[IKE] received DELETE for IKE_SA 0000-0003-private-to-0000-0014-private[1] Aug 5 13:40:46 zsitegate-00 charon: 03[IKE] deleting IKE_SA 0000-0003-private-to-0000-0014-private[1] between 10.0.3.177[CN=intersite-customer-0000-0003, OU=HAP Customers]...192.168.100.224[CN=intersite-customer-0000-0003, OU=HAP Customers] Aug 5 13:40:46 zsitegate-00 charon: 03[IKE] IKE_SA deleted Aug 5 13:40:46 zsitegate-00 charon: 03[CHD] updown: iptables: Bad rule (does a matching rule exist in that chain?). Aug 5 13:40:46 zsitegate-00 charon: 03[CHD] updown: iptables: Bad rule (does a matching rule exist in that chain?). Aug 5 13:40:46 zsitegate-00 vpn: - CN=intersite-customer-0000-0003, OU=HAP Customers 10.0.20.128/25 == 192.168.100.224 -- 10.0.3.177 == 10.0.3.128/25 Aug 5 13:40:46 zsitegate-00 charon: 03[ENC] generating INFORMATIONAL response 4 [ ] Aug 5 13:40:46 zsitegate-00 charon: 03[NET] sending packet: from 10.0.3.177[4500] to 192.168.100.224[4500] (76 bytes) Aug 5 13:40:47 zsitegate-00 charon: 02[KNL] creating acquire job for policy 10.0.3.129/32[icmp/8] === 10.0.20.177/32[icmp/8] with reqid {1} Aug 5 13:40:47 zsitegate-00 charon: 02[IKE] initiating IKE_SA 0000-0003-private-to-0000-0014-private[2] to 192.168.100.224 Aug 5 13:40:47 zsitegate-00 charon: 02[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ] Aug 5 13:40:47 zsitegate-00 charon: 02[NET] sending packet: from 10.0.3.177[500] to 192.168.100.224[500] (924 bytes) Aug 5 13:40:51 zsitegate-00 charon: 14[IKE] retransmit 1 of request with message ID 0 Aug 5 13:40:51 zsitegate-00 charon: 14[NET] sending packet: from 10.0.3.177[500] to 192.168.100.224[500] (924 bytes) Aug 5 13:40:53 zsitegate-00 charon: 00[DMN] signal of type SIGINT received. Shutting down Aug 5 13:40:53 zsitegate-00 charon: 00[IKE] destroying IKE_SA in state CONNECTING without notification Aug 5 13:45:01 zsitegate-00 CRON[28984]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1) SIte 2 Log Aug 5 13:35:18 zsitegate-01 charon: 00[DMN] Starting IKE charon daemon (strongSwan 5.1.1, Linux 3.8.0-30-raring-zdomu, x86_64) Aug 5 13:35:18 zsitegate-01 charon: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts' Aug 5 13:35:18 zsitegate-01 charon: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts' Aug 5 13:35:18 zsitegate-01 charon: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts' Aug 5 13:35:18 zsitegate-01 charon: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts' Aug 5 13:35:18 zsitegate-01 charon: 00[CFG] loading crls from '/etc/ipsec.d/crls' Aug 5 13:35:18 zsitegate-01 charon: 00[CFG] loading secrets from '/etc/ipsec.secrets' Aug 5 13:35:18 zsitegate-01 charon: 00[CFG] loaded RSA private key from '/etc/certificates/.intersite.myx509.key' Aug 5 13:35:18 zsitegate-01 charon: 00[LIB] loaded plugins: charon aes des rc2 sha1 sha2 md5 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl fips-prf gmp xcbc cmac hmac attr kernel-netlink resolve socket-default stroke updown xauth-generic Aug 5 13:35:18 zsitegate-01 charon: 00[LIB] unable to load 3 plugin features (3 due to unmet dependencies) Aug 5 13:35:18 zsitegate-01 charon: 00[JOB] spawning 16 worker threads Aug 5 13:35:18 zsitegate-01 charon: 11[CFG] received stroke: add ca 'ca1' Aug 5 13:35:18 zsitegate-01 charon: 11[CFG] loaded ca certificate "dnQualifier=HAP CA, OU=certificates, O=Zynstra Ltd, L=BATH, C=GB" from '/etc/certificates/ca/zynstra.pem' Aug 5 13:35:18 zsitegate-01 charon: 11[CFG] added ca 'ca1' Aug 5 13:35:18 zsitegate-01 charon: 13[CFG] received stroke: add connection '0000-0014-private-to-0000-0003-private' Aug 5 13:35:18 zsitegate-01 charon: 13[CFG] loaded certificate "CN=intersite-customer-0000-0003, OU=HAP Customers" from '/etc/certificates/.intersite.myx509.crt' Aug 5 13:35:18 zsitegate-01 charon: 13[CFG] added configuration '0000-0014-private-to-0000-0003-private' Aug 5 13:35:18 zsitegate-01 charon: 05[CFG] received stroke: route '0000-0014-private-to-0000-0003-private' Aug 5 13:35:19 zsitegate-01 charon: 04[KNL] creating acquire job for policy 10.0.20.132/32[tcp/55025] === 10.0.3.132/32[tcp/microsoft-ds] with reqid {1} Aug 5 13:35:19 zsitegate-01 charon: 04[IKE] initiating IKE_SA 0000-0014-private-to-0000-0003-private[1] to 192.168.100.48 Aug 5 13:35:19 zsitegate-01 charon: 04[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ] Aug 5 13:35:19 zsitegate-01 charon: 04[NET] sending packet: from 10.0.20.177[500] to 192.168.100.48[500] (924 bytes) Aug 5 13:35:19 zsitegate-01 charon: 06[NET] received packet: from 192.168.100.48[500] to 10.0.20.177[500] (465 bytes) Aug 5 13:35:19 zsitegate-01 charon: 06[ENC] parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ] Aug 5 13:35:19 zsitegate-01 charon: 06[IKE] local host is behind NAT, sending keep alives Aug 5 13:35:19 zsitegate-01 charon: 06[IKE] remote host is behind NAT Aug 5 13:35:19 zsitegate-01 charon: 06[IKE] received cert request for "dnQualifier=HAP CA, OU=certificates, O=Zynstra Ltd, L=BATH, C=GB" Aug 5 13:35:19 zsitegate-01 charon: 06[IKE] sending cert request for "dnQualifier=HAP CA, OU=certificates, O=Zynstra Ltd, L=BATH, C=GB" Aug 5 13:35:19 zsitegate-01 charon: 06[IKE] authentication of 'CN=intersite-customer-0000-0003, OU=HAP Customers' (myself) with RSA signature successful Aug 5 13:35:19 zsitegate-01 charon: 06[IKE] sending end entity cert "CN=intersite-customer-0000-0003, OU=HAP Customers" Aug 5 13:35:19 zsitegate-01 charon: 06[IKE] establishing CHILD_SA 0000-0014-private-to-0000-0003-private{1} Aug 5 13:35:19 zsitegate-01 charon: 06[ENC] generating IKE_AUTH request 1 [ IDi CERT CERTREQ IDr AUTH SA TSi TSr N(MOBIKE_SUP) N(ADD_6_ADDR) N(MULT_AUTH) N(EAP_ONLY) ] Aug 5 13:35:19 zsitegate-01 charon: 06[NET] sending packet: from 10.0.20.177[4500] to 192.168.100.48[4500] (1932 bytes) Aug 5 13:35:19 zsitegate-01 charon: 12[NET] received packet: from 192.168.100.48[4500] to 10.0.20.177[4500] (1644 bytes) Aug 5 13:35:19 zsitegate-01 charon: 12[ENC] parsed IKE_AUTH response 1 [ IDr CERT AUTH SA TSi TSr N(MOBIKE_SUP) N(ADD_6_ADDR) ] Aug 5 13:35:19 zsitegate-01 charon: 12[IKE] received end entity cert "CN=intersite-customer-0000-0003, OU=HAP Customers" Aug 5 13:35:19 zsitegate-01 charon: 12[CFG] using trusted intermediate ca certificate "dnQualifier=HAP CA, OU=certificates, O=Zynstra Ltd, L=BATH, C=GB" Aug 5 13:35:19 zsitegate-01 charon: 12[CFG] checking certificate status of "CN=intersite-customer-0000-0003, OU=HAP Customers" Aug 5 13:35:19 zsitegate-01 charon: 12[CFG] requesting ocsp status from 'http://localhost:8080/ejbca/publicweb/status/ocsp' ... Aug 5 13:35:19 zsitegate-01 charon: 12[LIB] unable to fetch from http://localhost:8080/ejbca/publicweb/status/ocsp, no capable fetcher found Aug 5 13:35:19 zsitegate-01 charon: 12[CFG] ocsp request to http://localhost:8080/ejbca/publicweb/status/ocsp failed Aug 5 13:35:19 zsitegate-01 charon: 12[CFG] ocsp check failed, fallback to crl Aug 5 13:35:19 zsitegate-01 charon: 12[CFG] fetching crl from 'http://localhost:8080/ejbca/publicweb/webdist/certdist?cmd=crl&issuer=DN=HAP%20CA,OU=certificates,O=Zynstra%20Ltd,L=BATH,C=GB' ... Aug 5 13:35:19 zsitegate-01 charon: 12[LIB] unable to fetch from http://localhost:8080/ejbca/publicweb/webdist/certdist?cmd=crl&issuer=DN=HAP%20CA,OU=certificates,O=Zynstra%20Ltd,L=BATH,C=GB, no capable fetcher found Aug 5 13:35:19 zsitegate-01 charon: 12[CFG] crl fetching failed Aug 5 13:35:19 zsitegate-01 charon: 12[CFG] certificate status is not available Aug 5 13:35:19 zsitegate-01 charon: 12[CFG] reached self-signed root ca with a path length of 0 Aug 5 13:35:19 zsitegate-01 charon: 12[CFG] using trusted certificate "CN=intersite-customer-0000-0003, OU=HAP Customers" Aug 5 13:35:19 zsitegate-01 charon: 12[IKE] authentication of 'CN=intersite-customer-0000-0003, OU=HAP Customers' with RSA signature successful Aug 5 13:35:19 zsitegate-01 charon: 12[IKE] IKE_SA 0000-0014-private-to-0000-0003-private[1] established between 10.0.20.177[CN=intersite-customer-0000-0003, OU=HAP Customers]...192.168.100.48[CN=intersite-customer-0000-0003, OU=HAP Customers] Aug 5 13:35:19 zsitegate-01 charon: 12[IKE] scheduling rekeying in 480s Aug 5 13:35:19 zsitegate-01 charon: 12[IKE] maximum IKE_SA lifetime 540s Aug 5 13:35:19 zsitegate-01 charon: 12[IKE] CHILD_SA 0000-0014-private-to-0000-0003-private{1} established with SPIs cf1ae00e_i c7cca7a5_o and TS 10.0.20.128/25 === 10.0.3.128/25 Aug 5 13:35:19 zsitegate-01 vpn: + CN=intersite-customer-0000-0003, OU=HAP Customers 10.0.3.128/25 == 192.168.100.48 -- 10.0.20.177 == 10.0.20.128/25 Aug 5 13:35:19 zsitegate-01 charon: 12[IKE] peer supports MOBIKE Aug 5 13:37:19 zsitegate-01 charon: 16[NET] received packet: from 192.168.100.48[4500] to 10.0.20.177[4500] (348 bytes) Aug 5 13:37:19 zsitegate-01 charon: 16[ENC] parsed CREATE_CHILD_SA request 0 [ N(REKEY_SA) SA No TSi TSr ] Aug 5 13:37:19 zsitegate-01 charon: 16[IKE] CHILD_SA 0000-0014-private-to-0000-0003-private{1} established with SPIs c021887d_i c6dc909b_o and TS 10.0.20.128/25 === 10.0.3.128/25 Aug 5 13:37:19 zsitegate-01 charon: 16[ENC] generating CREATE_CHILD_SA response 0 [ SA No TSi TSr ] Aug 5 13:37:19 zsitegate-01 charon: 16[NET] sending packet: from 10.0.20.177[4500] to 192.168.100.48[4500] (204 bytes) Aug 5 13:37:19 zsitegate-01 charon: 02[NET] received packet: from 192.168.100.48[4500] to 10.0.20.177[4500] (76 bytes) Aug 5 13:37:19 zsitegate-01 charon: 02[ENC] parsed INFORMATIONAL request 1 [ D ] Aug 5 13:37:19 zsitegate-01 charon: 02[IKE] received DELETE for ESP CHILD_SA with SPI c7cca7a5 Aug 5 13:37:19 zsitegate-01 charon: 02[IKE] closing CHILD_SA 0000-0014-private-to-0000-0003-private{1} with SPIs cf1ae00e_i (6717 bytes) c7cca7a5_o (5254 bytes) and TS 10.0.20.128/25 === 10.0.3.128/25 Aug 5 13:37:19 zsitegate-01 charon: 02[IKE] sending DELETE for ESP CHILD_SA with SPI cf1ae00e Aug 5 13:37:19 zsitegate-01 charon: 02[IKE] CHILD_SA closed Aug 5 13:37:19 zsitegate-01 charon: 02[ENC] generating INFORMATIONAL response 1 [ D ] Aug 5 13:37:19 zsitegate-01 charon: 02[NET] sending packet: from 10.0.20.177[4500] to 192.168.100.48[4500] (76 bytes) Aug 5 13:38:36 zsitegate-01 charon: 01[IKE] sending keep alive to 192.168.100.48[4500] Aug 5 13:39:19 zsitegate-01 charon: 06[KNL] creating rekey job for ESP CHILD_SA with SPI c021887d and reqid {1} Aug 5 13:39:19 zsitegate-01 charon: 06[IKE] establishing CHILD_SA 0000-0014-private-to-0000-0003-private{1} Aug 5 13:39:19 zsitegate-01 charon: 06[ENC] generating CREATE_CHILD_SA request 2 [ N(REKEY_SA) SA No TSi TSr ] Aug 5 13:39:19 zsitegate-01 charon: 06[NET] sending packet: from 10.0.20.177[4500] to 192.168.100.48[4500] (348 bytes) Aug 5 13:39:19 zsitegate-01 charon: 12[NET] received packet: from 192.168.100.48[4500] to 10.0.20.177[4500] (348 bytes) Aug 5 13:39:19 zsitegate-01 charon: 12[ENC] parsed CREATE_CHILD_SA request 2 [ N(REKEY_SA) SA No TSi TSr ] Aug 5 13:39:19 zsitegate-01 charon: 12[IKE] CHILD_SA 0000-0014-private-to-0000-0003-private{1} established with SPIs c878e1b3_i cc63239f_o and TS 10.0.20.128/25 === 10.0.3.128/25 Aug 5 13:39:19 zsitegate-01 charon: 12[IKE] detected CHILD_REKEY collision with CHILD_REKEY Aug 5 13:39:19 zsitegate-01 charon: 12[ENC] generating CREATE_CHILD_SA response 2 [ SA No TSi TSr ] Aug 5 13:39:19 zsitegate-01 charon: 12[NET] sending packet: from 10.0.20.177[4500] to 192.168.100.48[4500] (204 bytes) Aug 5 13:39:19 zsitegate-01 charon: 14[NET] received packet: from 192.168.100.48[4500] to 10.0.20.177[4500] (204 bytes) Aug 5 13:39:19 zsitegate-01 charon: 14[ENC] parsed CREATE_CHILD_SA response 2 [ SA No TSi TSr ] Aug 5 13:39:19 zsitegate-01 charon: 14[IKE] CHILD_SA 0000-0014-private-to-0000-0003-private{1} established with SPIs cee3eb14_i c2719bec_o and TS 10.0.20.128/25 === 10.0.3.128/25 Aug 5 13:39:19 zsitegate-01 charon: 14[IKE] CHILD_SA rekey collision won, deleting old child Aug 5 13:39:19 zsitegate-01 charon: 14[IKE] closing CHILD_SA 0000-0014-private-to-0000-0003-private{1} with SPIs c021887d_i (72905 bytes) c6dc909b_o (163224 bytes) and TS 10.0.20.128/25 === 10.0.3.128/25 Aug 5 13:39:19 zsitegate-01 charon: 14[IKE] sending DELETE for ESP CHILD_SA with SPI c021887d Aug 5 13:39:19 zsitegate-01 charon: 14[ENC] generating INFORMATIONAL request 3 [ D ] Aug 5 13:39:19 zsitegate-01 charon: 14[NET] sending packet: from 10.0.20.177[4500] to 192.168.100.48[4500] (76 bytes) Aug 5 13:39:19 zsitegate-01 charon: 11[NET] received packet: from 192.168.100.48[4500] to 10.0.20.177[4500] (76 bytes) Aug 5 13:39:19 zsitegate-01 charon: 11[ENC] parsed INFORMATIONAL request 3 [ D ] Aug 5 13:39:19 zsitegate-01 charon: 11[IKE] received DELETE for ESP CHILD_SA with SPI cc63239f Aug 5 13:39:19 zsitegate-01 charon: 11[IKE] closing CHILD_SA 0000-0014-private-to-0000-0003-private{1} with SPIs c878e1b3_i (0 bytes) cc63239f_o (0 bytes) and TS 10.0.20.128/25 === 10.0.3.128/25 Aug 5 13:39:19 zsitegate-01 charon: 11[IKE] sending DELETE for ESP CHILD_SA with SPI c878e1b3 Aug 5 13:39:19 zsitegate-01 charon: 11[IKE] CHILD_SA closed Aug 5 13:39:19 zsitegate-01 charon: 13[MGR] ignoring request with ID 3, already processing Aug 5 13:39:19 zsitegate-01 vpn: - CN=intersite-customer-0000-0003, OU=HAP Customers 10.0.3.128/25 == 192.168.100.48 -- 10.0.20.177 == 10.0.20.128/25 Aug 5 13:39:19 zsitegate-01 charon: 11[ENC] generating INFORMATIONAL response 3 [ D ] Aug 5 13:39:19 zsitegate-01 charon: 11[NET] sending packet: from 10.0.20.177[4500] to 192.168.100.48[4500] (76 bytes) Aug 5 13:39:23 zsitegate-01 charon: 02[IKE] retransmit 1 of request with message ID 3 Aug 5 13:39:23 zsitegate-01 charon: 02[NET] sending packet: from 10.0.20.177[4500] to 192.168.100.48[4500] (76 bytes) Aug 5 13:39:23 zsitegate-01 charon: 01[NET] received packet: from 192.168.100.48[4500] to 10.0.20.177[4500] (76 bytes) Aug 5 13:39:23 zsitegate-01 charon: 01[ENC] parsed INFORMATIONAL response 3 [ D ] Aug 5 13:39:23 zsitegate-01 charon: 01[IKE] received DELETE for ESP CHILD_SA with SPI c6dc909b Aug 5 13:39:23 zsitegate-01 charon: 01[IKE] CHILD_SA closed Aug 5 13:40:04 zsitegate-01 charon: 16[IKE] sending keep alive to 192.168.100.48[4500] Aug 5 13:40:46 zsitegate-01 charon: 00[DMN] signal of type SIGINT received. Shutting down Aug 5 13:40:46 zsitegate-01 charon: 00[CHD] updown: iptables: Bad rule (does a matching rule exist in that chain?). Aug 5 13:40:46 zsitegate-01 charon: 00[CHD] updown: iptables: Bad rule (does a matching rule exist in that chain?). Aug 5 13:40:46 zsitegate-01 vpn: - CN=intersite-customer-0000-0003, OU=HAP Customers 10.0.3.128/25 == 192.168.100.48 -- 10.0.20.177 == 10.0.20.128/25 Aug 5 13:40:46 zsitegate-01 charon: 00[IKE] deleting IKE_SA 0000-0014-private-to-0000-0003-private[1] between 10.0.20.177[CN=intersite-customer-0000-0003, OU=HAP Customers]...192.168.100.48[CN=intersite-customer-0000-0003, OU=HAP Customers] Aug 5 13:40:46 zsitegate-01 charon: 00[IKE] sending DELETE for IKE_SA 0000-0014-private-to-0000-0003-private[1] Aug 5 13:40:46 zsitegate-01 charon: 00[ENC] generating INFORMATIONAL request 4 [ D ] Aug 5 13:40:46 zsitegate-01 charon: 00[NET] sending packet: from 10.0.20.177[4500] to 192.168.100.48[4500] (76 bytes) Aug 5 13:45:01 zsitegate-01 CRON[1983]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1) Aug 5 13:50:01 zsitegate-01 CRON[2871]: (root) CMD (check-join-status) Steve Lee Senior Architect Phone: +44 (0)7474 647674 www.zynstra.com Zynstra is a private limited company registered in England and Wales (registered number 07864369). Our registered office is 5 New Street Square, London, EC4A 3TW and our headquarters are at Bath Ventures, Broad Quay, Bath, BA1 1UD. ________________________________________ From: Steve Lee Sent: 31 July 2014 12:40 To: Martin Willi Cc: [email protected] Subject: RE: [strongSwan] Rekey Collisions The logs I pasted were for the previous night and only for the bit where the collision occurred - I do have the logs for last night but there's rather a lot of it as there are multiple tunnels - I'll run it again with the patch and fewer tunnels. Running with these parameters now to try to increase the frequency of the problem ikelifetime=15m keylife=5m rekeymargin=1m keyingtries=%forever rekeyfuzz=0% keyexchange=ikev2 left=10.0.20.177 leftcert=/etc/certificates/.intersite.myx509.crt leftid="CN=intersite-customer-0000-0003, OU=HAP Customers" leftfirewall=yes auto=route dpdaction=hold reauth=no Thanks Steve ________________________________________ From: Martin Willi <[email protected]> Sent: 31 July 2014 11:16 To: Steve Lee Cc: [email protected] Subject: Re: [strongSwan] Rekey Collisions Steve, > If you cant see any problem in the log, I'll gather some more data > next time it happens. > 15[IKE] CHILD_SA rekey collision lost, deleting rekeyed child > 13[IKE] CHILD_SA rekey collision won, deleting old child That all looks like it works as expected. Each peer deletes the CHILD_SA it should, and the peers should end up with the same rekeyed CHILD_SA. > the SPIs of the left and right ends match at first but this morning > they are different. That's definitely strange. Even if the peers don't agree on the CHILD_SAs to keep or delete, I don't see why the SAs should be out of sync. Did this happen during the log you provided, or can you provide a log when this happens? Also, I've attached a patch that adds some additional debugging to check if we falsely lookup the CHILD_SA by the outbound SPI where this is not intended. Just a wild guess, not sure if it is related. > do I just accept that it will and do my best to reduce the likelihood > of collisions Even if they happen, it is no issue here. Collisions get resolved just fine every time for the many collisions I've produced. That should be true for both 5.1.1 and 5.2.0. Regards Martin _______________________________________________ Users mailing list [email protected] https://lists.strongswan.org/mailman/listinfo/users
