[strongSwan] Rekey Collisions
Steve Lee
steve.lee at zynstra.com
Tue Aug 5 16:32:44 CEST 2014
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: users at lists.strongswan.org
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 <martin at strongswan.org>
Sent: 31 July 2014 11:16
To: Steve Lee
Cc: users at lists.strongswan.org
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
More information about the Users
mailing list