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
