[strongSwan] OSPF == tons of security associations
Hose
hose+stongswan at bluemaggottowel.com
Thu Jan 5 20:31:32 CET 2017
What you say...Noel Kuntze (noel at familie-kuntze.de):
> On 03.01.2017 20:51, hose wrote:
> > I'm pasting the logs below since they're quite long even though they're
> > the past 10 minutes. If you notice it's rekeying and deleting SAs quite
> > often.
> The logs look wrong. How does the beginning look like when it starts establishing all those
> duplicate SAs?
>
> --
(old logs trimmed)
Ok so I restarted strongswan and it ran with one SA for awhile. Here are the logs from when it restarts; nothing weird.
Jan 4 21:02:49 plato charon: 00[DMN] Starting IKE charon daemon (strongSwan 5.2.1, Linux 3.2.0-4-686-pae, i686)
Jan 4 21:02:50 plato charon: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts'
Jan 4 21:02:50 plato charon: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts'
Jan 4 21:02:50 plato charon: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts'
Jan 4 21:02:50 plato charon: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts'
Jan 4 21:02:50 plato charon: 00[CFG] loading crls from '/etc/ipsec.d/crls'
Jan 4 21:02:50 plato charon: 00[CFG] loading secrets from '/etc/ipsec.secrets'
Jan 4 21:02:50 plato charon: 00[CFG] expanding file expression '/var/lib/strongswan/ipsec.secrets.inc' failed
Jan 4 21:02:50 plato charon: 00[CFG] loaded IKE secret for 206.212.243.50 50.31.158.132
Jan 4 21:02:50 plato charon: 00[LIB] loaded plugins: charon aes rc2 sha1 sha2 md5 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl fips-prf gmp agent xcbc hmac gcm attr kernel-netlink resolve socket-default stroke updown
Jan 4 21:02:50 plato charon: 00[LIB] unable to load 3 plugin features (3 due to unmet dependencies)
Jan 4 21:02:50 plato charon: 00[LIB] dropped capabilities, running as uid 0, gid 0
Jan 4 21:02:50 plato charon: 00[JOB] spawning 16 worker threads
Jan 4 21:02:50 plato charon: 08[CFG] received stroke: add connection 'larvae'
Jan 4 21:02:50 plato charon: 08[CFG] added configuration 'larvae'
Jan 4 21:02:50 plato charon: 09[CFG] received stroke: route 'larvae'
Jan 4 21:02:50 plato charon: 10[KNL] creating acquire job for policy 206.212.243.50/32[gre] === 50.31.158.132/32[gre] with reqid {1}
Jan 4 21:02:50 plato charon: 10[IKE] initiating IKE_SA larvae[1] to 50.31.158.132
Jan 4 21:02:50 plato charon: 10[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
Jan 4 21:02:50 plato charon: 10[NET] sending packet: from 206.212.243.50[500] to 50.31.158.132[500] (432 bytes)
Jan 4 21:02:50 plato charon: 12[NET] received packet: from 50.31.158.132[500] to 206.212.243.50[500] (432 bytes)
Jan 4 21:02:50 plato charon: 12[ENC] parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(MULT_AUTH) ]
Jan 4 21:02:50 plato charon: 12[IKE] authentication of '206.212.243.50' (myself) with pre-shared key
Jan 4 21:02:50 plato charon: 12[IKE] establishing CHILD_SA larvae{1}
Jan 4 21:02:50 plato charon: 12[ENC] generating IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH N(USE_TRANSP) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(MULT_AUTH) N(EAP_ONLY) ]
Jan 4 21:02:50 plato charon: 12[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (265 bytes)
Jan 4 21:02:50 plato charon: 13[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (305 bytes)
Jan 4 21:02:50 plato charon: 13[ENC] parsed IKE_AUTH response 1 [ IDr AUTH N(USE_TRANSP) SA TSi TSr N(AUTH_LFT) N(MOBIKE_SUP) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_6_ADDR) ]
Jan 4 21:02:50 plato charon: 13[IKE] authentication of '50.31.158.132' with pre-shared key successful
Jan 4 21:02:50 plato charon: 13[IKE] IKE_SA larvae[1] established between 206.212.243.50[206.212.243.50]...50.31.158.132[50.31.158.132]
Jan 4 21:02:50 plato charon: 13[IKE] scheduling reauthentication in 10210s
Jan 4 21:02:50 plato charon: 13[IKE] maximum IKE_SA lifetime 10750s
Jan 4 21:02:50 plato charon: 13[IKE] CHILD_SA larvae{1} established with SPIs c3c00a78_i c9f3ceba_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 21:02:50 plato charon: 13[IKE] received AUTH_LIFETIME of 10170s, scheduling reauthentication in 9630s
Jan 4 21:02:50 plato charon: 13[IKE] peer supports MOBIKE
Jan 4 21:02:50 plato charon: 14[NET] received packet: from 50.31.158.132[500] to 206.212.243.50[500] (432 bytes)
Jan 4 21:02:50 plato charon: 14[ENC] parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
Jan 4 21:02:50 plato charon: 14[IKE] 50.31.158.132 is initiating an IKE_SA
Jan 4 21:02:51 plato charon: 14[ENC] generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(MULT_AUTH) ]
Jan 4 21:02:51 plato charon: 14[NET] sending packet: from 206.212.243.50[500] to 50.31.158.132[500] (432 bytes)
Jan 4 21:02:51 plato charon: 15[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (353 bytes)
Jan 4 21:02:51 plato charon: 15[ENC] parsed IKE_AUTH request 1 [ IDi IDr AUTH N(USE_TRANSP) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_6_ADDR) N(MULT_AUTH) N(EAP_ONLY) ]
Jan 4 21:02:51 plato charon: 15[CFG] looking for peer configs matching 206.212.243.50[206.212.243.50]...50.31.158.132[50.31.158.132]
Jan 4 21:02:51 plato charon: 15[CFG] selected peer config 'larvae'
Jan 4 21:02:51 plato charon: 15[IKE] authentication of '50.31.158.132' with pre-shared key successful
Jan 4 21:02:51 plato charon: 15[IKE] peer supports MOBIKE
Jan 4 21:02:51 plato charon: 15[IKE] authentication of '206.212.243.50' (myself) with pre-shared key
Jan 4 21:02:51 plato charon: 15[IKE] deleting duplicate IKE_SA for peer '50.31.158.132' due to uniqueness policy
Jan 4 21:02:51 plato charon: 15[IKE] deleting IKE_SA larvae[1] between 206.212.243.50[206.212.243.50]...50.31.158.132[50.31.158.132]
Jan 4 21:02:51 plato charon: 15[IKE] sending DELETE for IKE_SA larvae[1]
Jan 4 21:02:51 plato charon: 15[ENC] generating INFORMATIONAL request 2 [ D ]
Jan 4 21:02:51 plato charon: 15[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (57 bytes)
Jan 4 21:02:51 plato charon: 15[IKE] IKE_SA larvae[2] established between 206.212.243.50[206.212.243.50]...50.31.158.132[50.31.158.132]
Jan 4 21:02:51 plato charon: 15[IKE] scheduling reauthentication in 9743s
Jan 4 21:02:51 plato charon: 15[IKE] maximum IKE_SA lifetime 10283s
Jan 4 21:02:51 plato charon: 15[IKE] CHILD_SA larvae{1} established with SPIs cfb96496_i c06b7973_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 21:02:51 plato charon: 15[ENC] generating IKE_AUTH response 1 [ IDr AUTH N(USE_TRANSP) SA TSi TSr N(AUTH_LFT) N(MOBIKE_SUP) N(ADD_4_ADDR) ]
Jan 4 21:02:51 plato charon: 15[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (209 bytes)
Jan 4 21:02:51 plato charon: 16[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (49 bytes)
Jan 4 21:02:51 plato charon: 16[ENC] parsed INFORMATIONAL response 2 [ ]
Jan 4 21:02:51 plato charon: 16[IKE] IKE_SA deleted
It then rekeyed at appropriate intervals, again with only one SA (as expected):
Jan 4 21:47:03 plato charon: 11[KNL] creating rekey job for ESP CHILD_SA with SPI c06b7973 and reqid {1}
Jan 4 21:47:03 plato charon: 12[IKE] establishing CHILD_SA larvae{1}
Jan 4 21:47:03 plato charon: 12[ENC] generating CREATE_CHILD_SA request 0 [ N(REKEY_SA) N(USE_TRANSP) SA No KE TSi TSr ]
Jan 4 21:47:03 plato charon: 12[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (397 bytes)
Jan 4 21:47:03 plato charon: 13[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (385 bytes)
Jan 4 21:47:03 plato charon: 13[ENC] parsed CREATE_CHILD_SA response 0 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 4 21:47:03 plato charon: 13[IKE] CHILD_SA larvae{1} established with SPIs cf3b2040_i cff345ff_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 21:47:03 plato charon: 13[IKE] closing CHILD_SA larvae{1} with SPIs cfb96496_i (479804 bytes) c06b7973_o (8513102 bytes) and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 21:47:03 plato charon: 13[IKE] sending DELETE for ESP CHILD_SA with SPI cfb96496
Jan 4 21:47:03 plato charon: 13[ENC] generating INFORMATIONAL request 1 [ D ]
Jan 4 21:47:03 plato charon: 13[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (61 bytes)
Jan 4 21:47:03 plato charon: 14[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (61 bytes)
Jan 4 21:47:03 plato charon: 14[ENC] parsed INFORMATIONAL response 1 [ D ]
Jan 4 21:47:03 plato charon: 14[IKE] received DELETE for ESP CHILD_SA with SPI c06b7973
Jan 4 21:47:03 plato charon: 14[IKE] CHILD_SA closed
Jan 4 22:32:52 plato charon: 08[KNL] creating rekey job for ESP CHILD_SA with SPI cff345ff and reqid {1}
Jan 4 22:32:52 plato charon: 08[IKE] establishing CHILD_SA larvae{1}
Jan 4 22:32:52 plato charon: 08[ENC] generating CREATE_CHILD_SA request 2 [ N(REKEY_SA) N(USE_TRANSP) SA No KE TSi TSr ]
Jan 4 22:32:52 plato charon: 08[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (397 bytes)
Jan 4 22:32:52 plato charon: 10[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (385 bytes)
Jan 4 22:32:52 plato charon: 10[ENC] parsed CREATE_CHILD_SA response 2 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 4 22:32:52 plato charon: 10[IKE] CHILD_SA larvae{1} established with SPIs c9d86603_i c2348aa3_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 22:32:52 plato charon: 10[IKE] closing CHILD_SA larvae{1} with SPIs cf3b2040_i (573316 bytes) cff345ff_o (8863280 bytes) and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 22:32:52 plato charon: 10[IKE] sending DELETE for ESP CHILD_SA with SPI cf3b2040
Jan 4 22:32:52 plato charon: 10[ENC] generating INFORMATIONAL request 3 [ D ]
Jan 4 22:32:52 plato charon: 10[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (61 bytes)
Jan 4 22:32:52 plato charon: 12[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (61 bytes)
Jan 4 22:32:52 plato charon: 12[ENC] parsed INFORMATIONAL response 3 [ D ]
Jan 4 22:32:52 plato charon: 12[IKE] received DELETE for ESP CHILD_SA with SPI cff345ff
Jan 4 22:32:52 plato charon: 12[IKE] CHILD_SA closed
Each time it re-keyed and killed the old SAs
Jan 4 21:47:03 plato charon: 11[KNL] creating rekey job for ESP CHILD_SA with SPI c06b7973 and reqid {1}
Jan 4 21:47:03 plato charon: 12[IKE] establishing CHILD_SA larvae{1}
Jan 4 21:47:03 plato charon: 12[ENC] generating CREATE_CHILD_SA request 0 [ N(REKEY_SA) N(USE_TRANSP) SA No KE TSi TSr ]
Jan 4 21:47:03 plato charon: 12[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (397 bytes)
Jan 4 21:47:03 plato charon: 13[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (385 bytes)
Jan 4 21:47:03 plato charon: 13[ENC] parsed CREATE_CHILD_SA response 0 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 4 21:47:03 plato charon: 13[IKE] CHILD_SA larvae{1} established with SPIs cf3b2040_i cff345ff_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 21:47:03 plato charon: 13[IKE] closing CHILD_SA larvae{1} with SPIs cfb96496_i (479804 bytes) c06b7973_o (8513102 bytes) and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 21:47:03 plato charon: 13[IKE] sending DELETE for ESP CHILD_SA with SPI cfb96496
Jan 4 21:47:03 plato charon: 13[ENC] generating INFORMATIONAL request 1 [ D ]
Jan 4 21:47:03 plato charon: 13[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (61 bytes)
Jan 4 21:47:03 plato charon: 14[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (61 bytes)
Jan 4 21:47:03 plato charon: 14[ENC] parsed INFORMATIONAL response 1 [ D ]
Jan 4 21:47:03 plato charon: 14[IKE] received DELETE for ESP CHILD_SA with SPI c06b7973
Jan 4 21:47:03 plato charon: 14[IKE] CHILD_SA closed
Jan 4 22:32:52 plato charon: 08[KNL] creating rekey job for ESP CHILD_SA with SPI cff345ff and reqid {1}
Jan 4 22:32:52 plato charon: 08[IKE] establishing CHILD_SA larvae{1}
Jan 4 22:32:52 plato charon: 08[ENC] generating CREATE_CHILD_SA request 2 [ N(REKEY_SA) N(USE_TRANSP) SA No KE TSi TSr ]
Jan 4 22:32:52 plato charon: 08[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (397 bytes)
Jan 4 22:32:52 plato charon: 10[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (385 bytes)
Jan 4 22:32:52 plato charon: 10[ENC] parsed CREATE_CHILD_SA response 2 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 4 22:32:52 plato charon: 10[IKE] CHILD_SA larvae{1} established with SPIs c9d86603_i c2348aa3_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 22:32:52 plato charon: 10[IKE] closing CHILD_SA larvae{1} with SPIs cf3b2040_i (573316 bytes) cff345ff_o (8863280 bytes) and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 22:32:52 plato charon: 10[IKE] sending DELETE for ESP CHILD_SA with SPI cf3b2040
Jan 4 22:32:52 plato charon: 10[ENC] generating INFORMATIONAL request 3 [ D ]
Jan 4 22:32:52 plato charon: 10[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (61 bytes)
Jan 4 22:32:52 plato charon: 12[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (61 bytes)
Jan 4 22:32:52 plato charon: 12[ENC] parsed INFORMATIONAL response 3 [ D ]
Jan 4 22:32:52 plato charon: 12[IKE] received DELETE for ESP CHILD_SA with SPI cff345ff
Jan 4 22:32:52 plato charon: 12[IKE] CHILD_SA closed
There is one more rekey, and then an ike init occurs:
Jan 4 23:38:59 plato charon: 09[NET] received packet: from 50.31.158.132[500] to 206.212.243.50[500] (432 bytes)
Jan 4 23:38:59 plato charon: 09[ENC] parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
Jan 4 23:38:59 plato charon: 09[IKE] 50.31.158.132 is initiating an IKE_SA
Jan 4 23:38:59 plato charon: 09[ENC] generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(MULT_AUTH) ]
Jan 4 23:38:59 plato charon: 09[NET] sending packet: from 206.212.243.50[500] to 50.31.158.132[500] (432 bytes)
Jan 4 23:39:09 plato charon: 14[IKE] sending DPD request
Jan 4 23:39:09 plato charon: 14[ENC] generating INFORMATIONAL request 6 [ ]
Jan 4 23:39:09 plato charon: 14[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (49 bytes)
Jan 4 23:39:11 plato charon: 13[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (329 bytes)
Jan 4 23:39:11 plato charon: 13[ENC] parsed IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH N(USE_TRANSP) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_6_ADDR) N(MULT_AUTH) N(EAP_ONLY) ]
Jan 4 23:39:11 plato charon: 13[CFG] looking for peer configs matching 206.212.243.50[206.212.243.50]...50.31.158.132[50.31.158.132]
Jan 4 23:39:11 plato charon: 13[CFG] selected peer config 'larvae'
Jan 4 23:39:11 plato charon: 13[IKE] authentication of '50.31.158.132' with pre-shared key successful
Jan 4 23:39:11 plato charon: 13[IKE] peer supports MOBIKE
Jan 4 23:39:11 plato charon: 13[IKE] destroying duplicate IKE_SA for peer '50.31.158.132', received INITIAL_CONTACT
Jan 4 23:39:11 plato charon: 13[IKE] authentication of '206.212.243.50' (myself) with pre-shared key
Jan 4 23:39:11 plato charon: 13[IKE] IKE_SA larvae[3] established between 206.212.243.50[206.212.243.50]...50.31.158.132[50.31.158.132]
Jan 4 23:39:11 plato charon: 13[IKE] scheduling reauthentication in 9997s
Jan 4 23:39:11 plato charon: 13[IKE] maximum IKE_SA lifetime 10537s
Jan 4 23:39:11 plato charon: 13[IKE] CHILD_SA larvae{1} established with SPIs c348600a_i c41700f8_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 23:39:11 plato charon: 13[ENC] generating IKE_AUTH response 1 [ IDr AUTH N(USE_TRANSP) SA TSi TSr N(AUTH_LFT) N(MOBIKE_SUP) N(ADD_4_ADDR) ]
Jan 4 23:39:11 plato charon: 13[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (209 bytes)
Jan 4 23:39:11 plato charon: 11[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (417 bytes)
Jan 4 23:39:11 plato charon: 11[ENC] parsed CREATE_CHILD_SA request 2 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 4 23:39:11 plato charon: 11[IKE] CHILD_SA larvae{1} established with SPIs c6660125_i c06cafb1_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 4 23:39:11 plato charon: 11[ENC] generating CREATE_CHILD_SA response 2 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 4 23:39:11 plato charon: 11[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (385 bytes)
Note the two sets of SAs created. Then a bit later one more ike init:
Jan 5 00:25:00 plato charon: 02[NET] received packet: from 50.31.158.132[500] to 206.212.243.50[500] (432 bytes)
Jan 5 00:25:00 plato charon: 02[ENC] parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
Jan 5 00:25:00 plato charon: 02[IKE] 50.31.158.132 is initiating an IKE_SA
Jan 5 00:25:00 plato charon: 02[ENC] generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(MULT_AUTH) ]
Jan 5 00:25:00 plato charon: 02[NET] sending packet: from 206.212.243.50[500] to 50.31.158.132[500] (432 bytes)
Jan 5 00:25:10 plato charon: 08[IKE] sending DPD request
Jan 5 00:25:10 plato charon: 08[ENC] generating INFORMATIONAL request 0 [ ]
Jan 5 00:25:10 plato charon: 08[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (49 bytes)
Jan 5 00:25:12 plato charon: 13[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (329 bytes)
Jan 5 00:25:12 plato charon: 13[ENC] parsed IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH N(USE_TRANSP) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_6_ADDR) N(MULT_AUTH) N(EAP_ONLY) ]
Jan 5 00:25:12 plato charon: 13[CFG] looking for peer configs matching 206.212.243.50[206.212.243.50]...50.31.158.132[50.31.158.132]
Jan 5 00:25:12 plato charon: 13[CFG] selected peer config 'larvae'
Jan 5 00:25:12 plato charon: 13[IKE] authentication of '50.31.158.132' with pre-shared key successful
Jan 5 00:25:12 plato charon: 13[IKE] peer supports MOBIKE
Jan 5 00:25:12 plato charon: 13[IKE] destroying duplicate IKE_SA for peer '50.31.158.132', received INITIAL_CONTACT
Jan 5 00:25:12 plato charon: 13[IKE] authentication of '206.212.243.50' (myself) with pre-shared key
Jan 5 00:25:12 plato charon: 13[IKE] IKE_SA larvae[4] established between 206.212.243.50[206.212.243.50]...50.31.158.132[50.31.158.132]
Jan 5 00:25:12 plato charon: 13[IKE] scheduling reauthentication in 10202s
Jan 5 00:25:12 plato charon: 13[IKE] maximum IKE_SA lifetime 10742s
Jan 5 00:25:12 plato charon: 13[IKE] CHILD_SA larvae{1} established with SPIs c59ffcbc_i c7728ccf_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 5 00:25:12 plato charon: 13[ENC] generating IKE_AUTH response 1 [ IDr AUTH N(USE_TRANSP) SA TSi TSr N(AUTH_LFT) N(MOBIKE_SUP) N(ADD_4_ADDR) ]
Jan 5 00:25:12 plato charon: 13[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (209 bytes)
Jan 5 00:25:12 plato charon: 14[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (385 bytes)
Jan 5 00:25:12 plato charon: 14[ENC] parsed CREATE_CHILD_SA request 2 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 5 00:25:12 plato charon: 14[IKE] CHILD_SA larvae{1} established with SPIs c8d1c5fb_i c1330f50_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 5 00:25:12 plato charon: 14[ENC] generating CREATE_CHILD_SA response 2 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 5 00:25:12 plato charon: 14[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (385 bytes)
Jan 5 00:25:12 plato charon: 11[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (417 bytes)
Jan 5 00:25:12 plato charon: 11[ENC] parsed CREATE_CHILD_SA request 3 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 5 00:25:12 plato charon: 11[IKE] CHILD_SA larvae{1} established with SPIs c0d2d7ac_i c01be420_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 5 00:25:12 plato charon: 11[ENC] generating CREATE_CHILD_SA response 3 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 5 00:25:12 plato charon: 11[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (385 bytes)
Note there are three sets of active SAs now: c59ffcbc, c7728ccf, c8d1c5fb,
c1330f50, c0d2d7ac, and c01be420.
It eventually rekeys two of the sets, and the third gets killed along
with the others during a subsequent ike init. But then on that init,
it now rekeys FOUR sets of SAs:
Jan 5 01:10:45 plato charon: 10[NET] received packet: from 50.31.158.132[500] to 206.212.243.50[500] (432 bytes)
Jan 5 01:10:45 plato charon: 10[ENC] parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
Jan 5 01:10:45 plato charon: 10[IKE] 50.31.158.132 is initiating an IKE_SA
Jan 5 01:10:45 plato charon: 10[ENC] generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(MULT_AUTH) ]
Jan 5 01:10:45 plato charon: 10[NET] sending packet: from 206.212.243.50[500] to 50.31.158.132[500] (432 bytes)
Jan 5 01:10:45 plato charon: 12[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (329 bytes)
Jan 5 01:10:45 plato charon: 12[ENC] parsed IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH N(USE_TRANSP) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_6_ADDR) N(MULT_AUTH) N(EAP_ONLY) ]
Jan 5 01:10:45 plato charon: 12[CFG] looking for peer configs matching 206.212.243.50[206.212.243.50]...50.31.158.132[50.31.158.132]
Jan 5 01:10:45 plato charon: 12[CFG] selected peer config 'larvae'
Jan 5 01:10:45 plato charon: 12[IKE] authentication of '50.31.158.132' with pre-shared key successful
Jan 5 01:10:45 plato charon: 12[IKE] peer supports MOBIKE
Jan 5 01:10:45 plato charon: 12[IKE] destroying duplicate IKE_SA for peer '50.31.158.132', received INITIAL_CONTACT
Jan 5 01:10:45 plato charon: 12[IKE] authentication of '206.212.243.50' (myself) with pre-shared key
Jan 5 01:10:45 plato charon: 12[IKE] IKE_SA larvae[5] established between 206.212.243.50[206.212.243.50]...50.31.158.132[50.31.158.132]
Jan 5 01:10:46 plato charon: 12[IKE] scheduling reauthentication in 10135s
Jan 5 01:10:46 plato charon: 12[IKE] maximum IKE_SA lifetime 10675s
Jan 5 01:10:46 plato charon: 12[IKE] CHILD_SA larvae{1} established with SPIs cfd79b52_i cf545fe1_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 5 01:10:46 plato charon: 12[ENC] generating IKE_AUTH response 1 [ IDr AUTH N(USE_TRANSP) SA TSi TSr N(AUTH_LFT) N(MOBIKE_SUP) N(ADD_4_ADDR) ]
Jan 5 01:10:46 plato charon: 12[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (209 bytes)
Jan 5 01:10:46 plato charon: 16[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (385 bytes)
Jan 5 01:10:46 plato charon: 16[ENC] parsed CREATE_CHILD_SA request 2 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 5 01:10:46 plato charon: 16[IKE] CHILD_SA larvae{1} established with SPIs c248eef9_i c1c60030_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 5 01:10:46 plato charon: 16[ENC] generating CREATE_CHILD_SA response 2 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 5 01:10:46 plato charon: 16[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (385 bytes)
Jan 5 01:10:46 plato charon: 08[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (385 bytes)
Jan 5 01:10:46 plato charon: 08[ENC] parsed CREATE_CHILD_SA request 3 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 5 01:10:46 plato charon: 08[IKE] CHILD_SA larvae{1} established with SPIs c8080990_i ca3ab22b_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 5 01:10:46 plato charon: 08[ENC] generating CREATE_CHILD_SA response 3 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 5 01:10:46 plato charon: 08[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (385 bytes)
Jan 5 01:10:46 plato charon: 11[NET] received packet: from 50.31.158.132[4500] to 206.212.243.50[4500] (417 bytes)
Jan 5 01:10:46 plato charon: 11[ENC] parsed CREATE_CHILD_SA request 4 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 5 01:10:46 plato charon: 11[IKE] CHILD_SA larvae{1} established with SPIs c2e8a16e_i cf7a5c54_o and TS 206.212.243.50/32 === 50.31.158.132/32
Jan 5 01:10:46 plato charon: 11[ENC] generating CREATE_CHILD_SA response 4 [ N(USE_TRANSP) SA No KE TSi TSr ]
Jan 5 01:10:46 plato charon: 11[NET] sending packet: from 206.212.243.50[4500] to 50.31.158.132[4500] (385 bytes)
So from what I can tell each time it's doing an IKE re-key it's creating an
additional set of SAs. Any idea why this is occurring?
More information about the Users
mailing list