[Swan] SA lifetime too short, less than configured
Ivan Kuznetsov
kia at solvo.ru
Thu May 20 16:33:53 UTC 2021
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
More information about the Swan
mailing list