[Swan] SA lifetime too short, less than configured
Ivan Kuznetsov
kia at solvo.ru
Thu May 20 17:33:36 UTC 2021
Gzipped log for time 00:42:14 is attached
As I understand, other side (Cisco ASA) sends ISAKMP_v2_INFORMATIONAL
message contains ISAKMP_NEXT_v2D payload asks to delete the #103354 SA
20.05.2021 19:33, Ivan Kuznetsov пишет:
> Hello Paul
>
> 17.05.2021 18:01, Paul Wouters пишет:
>> On Mon, 17 May 2021, Ivan Kuznetsov wrote:
>>
>>> Yes, all the bkp* has the same life times:
>>>
>>> [root at vpn3 ipsec.d]# ipsec auto --status | grep bkp | grep ike_life
>>> 000 "bkp/0x1": ike_life: 86400s; ipsec_life: 28800s; replay_window:
>>> 32; rekey_margin: 300s; rekey_fuzz: 100%; keyingtries: 3;
>>> 000 "bkp/0x2": ike_life: 86400s; ipsec_life: 28800s; replay_window:
>>> 32; rekey_margin: 300s; rekey_fuzz: 100%; keyingtries: 3;
>>> 000 "bkp/0x3": ike_life: 86400s; ipsec_life: 28800s; replay_window:
>>> 32; rekey_margin: 300s; rekey_fuzz: 100%; keyingtries: 3;
>>> 000 "bkp/0x4": ike_life: 86400s; ipsec_life: 28800s; replay_window:
>>> 32; rekey_margin: 300s; rekey_fuzz: 100%; keyingtries: 3;
>>
>> That's good
>>
>>>> Just over one hour is really weird. Can you run with
>>>> plutodebug=all,tmi
>>>> and show the log lines you see between these two messages?
>>>
>>> It can be a bit problematic as this ipsec instance handle 20+ active
>>> production connections with different peers/clients. It seems that
>>> 'ipsec whack --name bkp/0xN --debug all,tmi' does not have any
>>> logging effect. I'm afraid enable debug logging globally will slow
>>> down the connections and make a huge log.
>>
>> Ok, how about: ipsec status |grep STATE_ |grep bkp/
>
> I wrote a simple script logging 'ipsec status |grep STATE_ |grep bkp/'
> every 10s. Here is output (non-interesting lines skipped):
>
> 18.05.2021 23:41:28
> 000 #103273: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82325s; newest ISAKMP; idle;
> 000 #103274: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24764s; newest IPSEC; eroute owner; isakmp#103273; idle;
> 18.05.2021 23:41:38
> 000 #103273: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82315s; newest ISAKMP; idle;
> 000 #103274: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24754s; newest IPSEC; eroute owner; isakmp#103273; idle;
> 18.05.2021 23:41:48
> 000 #103273: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82305s; newest ISAKMP; idle;
> 000 #103274: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24744s; newest IPSEC; eroute owner; isakmp#103273; idle;
> 18.05.2021 23:41:58
> 000 #103273: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82295s; newest ISAKMP; idle;
> 000 #103274: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24734s; newest IPSEC; eroute owner; isakmp#103273; idle;
> 18.05.2021 23:42:08
> 000 #103273: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82285s; newest ISAKMP; idle;
> 000 #103274: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24724s; newest IPSEC; eroute owner; isakmp#103273; idle;
> 18.05.2021 23:42:18
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 86054s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 28465s; newest IPSEC; eroute owner; isakmp#103354; idle;
> 18.05.2021 23:42:28
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 86044s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 28455s; newest IPSEC; eroute owner; isakmp#103354; idle;
> 18.05.2021 23:42:38
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 86034s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 28445s; newest IPSEC; eroute owner; isakmp#103354; idle;
> 18.05.2021 23:42:48
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 86024s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 28435s; newest IPSEC; eroute owner; isakmp#103354; idle;
>
> [...]
>
> 19.05.2021 00:41:14
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82518s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24929s; newest IPSEC; eroute owner; isakmp#103354; idle;
> 19.05.2021 00:41:24
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82508s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24919s; newest IPSEC; eroute owner; isakmp#103354; idle;
> 19.05.2021 00:41:34
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82498s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24909s; newest IPSEC; eroute owner; isakmp#103354; idle;
> 19.05.2021 00:41:44
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82488s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24899s; newest IPSEC; eroute owner; isakmp#103354; idle;
> 19.05.2021 00:41:54
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82478s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24889s; newest IPSEC; eroute owner; isakmp#103354; idle;
> 19.05.2021 00:42:04
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82468s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24879s; newest IPSEC; eroute owner; isakmp#103354; idle;
> 19.05.2021 00:42:14
> 000 #103354: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 82458s; newest ISAKMP; idle;
> 000 #103355: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 24869s; newest IPSEC; eroute owner; isakmp#103354; idle;
> 19.05.2021 00:42:24
> 000 #103446: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 85858s; newest ISAKMP; idle;
> 000 #103447: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 28245s; newest IPSEC; eroute owner; isakmp#103446; idle;
> 19.05.2021 00:42:34
> 000 #103446: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 85848s; newest ISAKMP; idle;
> 000 #103447: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 28235s; newest IPSEC; eroute owner; isakmp#103446; idle;
> 19.05.2021 00:42:44
> 000 #103446: "bkp/0x2":500 STATE_PARENT_I3 (PARENT SA established);
> EVENT_SA_REKEY in 85838s; newest ISAKMP; idle;
> 000 #103447: "bkp/0x2":500 STATE_V2_IPSEC_I (IPsec SA established);
> EVENT_SA_REKEY in 28225s; newest IPSEC; eroute owner; isakmp#103446; idle;
>
> Ordinary log for this interval:
>
> May 18 23:42:14.600749: "bkp/0x2" #103274: deleting other state #103274
> (STATE_CHILDSA_DEL) aged 3600.063s and NOT sending notification
> May 18 23:42:14.609714: "bkp/0x2" #103273: deleting state
> (STATE_IKESA_DEL) aged 3600.113s and NOT sending notification
> May 18 23:42:14.609764: "bkp/0x2" #103273: deleting IKE SA but
> connection is supposed to remain up; schedule EVENT_REVIVE_CONNS
> May 18 23:42:14.609867: "bkp/0x2": initiating connection which received
> a Delete/Notify but must remain up per local policy
> May 18 23:42:14.609908: "bkp/0x2" #103354: initiating IKEv2 IKE SA
> May 18 23:42:14.610786: "bkp/0x2" #103354: STATE_PARENT_I1: sent v2I1,
> expected v2R1
> May 18 23:42:14.650282: "bkp/0x2" #103354: sending INITIAL_CONTACT
> May 18 23:42:14.650418: "bkp/0x2" #103355: STATE_PARENT_I2: sent v2I2,
> expected v2R2 {auth=IKEv2 cipher=AES_CBC_256 integ=HMAC_SHA2_256_128
> prf=HMAC_SHA2_256 group=MODP2048}
> May 18 23:42:14.687609: "bkp/0x2" #103355: IKEv2 mode peer ID is
> ID_IPV4_ADDR: '55.66.77.88'
> May 18 23:42:14.687716: "bkp/0x2" #103355: Authenticated using
> authby=secret
> May 18 23:42:14.701412: "bkp/0x2" #103355: negotiated connection
> [172.16.80.0-172.16.95.255:0-65535 0] ->
> [10.1.102.0-10.1.102.255:0-65535 0]
> May 18 23:42:14.701439: "bkp/0x2" #103355: STATE_V2_IPSEC_I: IPsec SA
> established tunnel mode {ESP=>0x1ca2037a <0x9c10a01e
> xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=none DPD=passive}
> May 19 00:42:14.722020: "bkp/0x2" #103355 CHILDSA_DEL: deleting other
> state #103355 (STATE_CHILDSA_DEL) aged 3600.071s and NOT sending
> notification
> May 19 00:42:14.743932: "bkp/0x2" #103354 IKESA_DEL: deleting state
> (STATE_IKESA_DEL) aged 3600.134s and NOT sending notification
> May 19 00:42:14.744043: "bkp/0x2" #103354 IKESA_DEL: deleting IKE SA but
> connection is supposed to remain up; schedule EVENT_REVIVE_CONNS
> May 19 00:42:14.744460: "bkp/0x2": initiating connection which received
> a Delete/Notify but must remain up per local policy
> May 19 00:42:14.744732: "bkp/0x2" #103446 PARENT_I0: initiating IKEv2
> IKE SA
> May 19 00:42:14.749753: "bkp/0x2" #103446 PARENT_I1: STATE_PARENT_I1:
> sent v2I1, expected v2R1
> May 19 00:42:14.791897: "bkp/0x2" #103446 PARENT_I2: sending
> INITIAL_CONTACT
> May 19 00:42:14.794066: "bkp/0x2" #103447 PARENT_I2: STATE_PARENT_I2:
> sent v2I2, expected v2R2 {auth=IKEv2 cipher=AES_CBC_256
> integ=HMAC_SHA2_256_128 prf=HMAC_SHA2_256 group=MODP2048}
> May 19 00:42:14.831512: "bkp/0x2" #103447 PARENT_I2: IKEv2 mode peer ID
> is ID_IPV4_ADDR: '55.66.77.88'
> May 19 00:42:14.832049: "bkp/0x2" #103447 PARENT_I2: Authenticated using
> authby=secret
> May 19 00:42:14.842184: "bkp/0x2" #103447 V2_IPSEC_I: negotiated
> connection [172.16.80.0-172.16.95.255:0-65535 0] ->
> [10.1.102.0-10.1.102.255:0-65535 0]
> May 19 00:42:14.842193: "bkp/0x2" #103447 V2_IPSEC_I: STATE_V2_IPSEC_I:
> IPsec SA established tunnel mode {ESP=>0xba426de0 <0x1e908659
> xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=none DPD=passive}
>
> Note the time passed between tunnel restarts is exact 3600s=1h
>
> I have collect a debug log for that time but it contains a lot of info
> about other tunnels (~700K lines for 1h). How can I select lines for
> "bkp" tunnel events? Grep'ing by 'bkp|103354|103355' it seems loosing
> some info. May be I will share some seconds just before "interesting"
> time 00:42:14?
--
Regards, Ivan Kuznetsov
SOLVO ltd
-------------- next part --------------
A non-text attachment was scrubbed...
Name: bkp-19may-004214-log.txt.gz
Type: application/gzip
Size: 31411 bytes
Desc: not available
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20210520/d24301c0/attachment-0001.gz>
More information about the Swan
mailing list