[strongSwan] Reporting Issue:Old CHILD_SA not getting cleared

Tue Apr 10 20:04:53 CEST 2012

Hi Tobias,

Thanks a lot for the response. 
We are looking into the possibilities of upgrading to the latest charon version but it looks unlikely until we are able establish that the issue is really linked to old the charon version.
In the mean time we have analysed the charon logs and have an observation. We would request you to share your opinion on this if possible.

Provided below is an excerpt of the log:

1) Rekeying for CHILD SA r1cmptun~cmptun{1}

Mar 28 09:51:42.231110 info CLA-0 charon: 09[IKE] sending DPD request
Mar 28 09:51:53.115294 info CLA-0 charon: 12[IKE] establishing CHILD_SA r1cmptun~cmptun{1}
Mar 28 09:51:53.125240 info CLA-0 FPM[766]: fpm_ipsec_sa_create:
Mar 28 09:51:53.125372 info CLA-0 FPM[766]: add SA success
Mar 28 09:51:53.127893 info CLA-0 FPM[766]: fpm_ipsec_sa_create:
Mar 28 09:51:53.128004 info CLA-0 FPM[766]: add SA success
Mar 28 09:51:53.128174 info CLA-0 FPM[766]: add SP success
Mar 28 09:51:53.128343 info CLA-0 FPM[766]: add SP success
Mar 28 09:51:53.212338 info CLA-0 charon: 13[IKE] CHILD_SA r1cmptun~cmptun{1} established with SPIs c4a73d7e_i a8423011_o and TS 192.168.0.0/16[0] === 10.0.0.0/8[0] 
Mar 28 09:51:53.341079 info CLA-0 charon: 13[IKE] closing CHILD_SA r1cmptun~cmptun{1} with SPIs c4beef54_i 0ec1006d_o and TS 192.168.0.0/16[0] === 10.0.0.0/8[0] 
Mar 28 09:51:53.383684 info CLA-0 charon: 13[IKE] sending DELETE for ESP CHILD_SA with SPI c4beef54
Mar 28 09:51:53.386884 info CLA-0 charon: 14[IKE] received DELETE for ESP CHILD_SA with SPI 0ec1006d
Mar 28 09:51:53.387526 info CLA-0 charon: 14[IKE] CHILD_SA closed
Mar 28 09:51:53.387579 info CLA-0 FPM[766]: fpm_ipsec_sa_delete:
Mar 28 09:51:53.387665 info CLA-0 FPM[766]: del SA success
Mar 28 09:51:53.387737 info CLA-0 FPM[766]: fpm_ipsec_sa_delete:
Mar 28 09:51:53.387877 info CLA-0 FPM[766]: del SA success
Mar 28 09:52:23.243414 info CLA-0 charon: 03[IKE] sending DPD request

2) Rekeying of IKE_SA with name r1cmptun~cmptun [2] [compare this to the older IKE_SA name r1cmptun~cmptun[1]]

Mar 28 09:52:40.111588 info CLA-0 charon: 11[IKE] deleting IKE_SA r1cmptun~cmptun[1] between 10.69.200.89[C=FI, O=NSN, OU=SyVe, CN=IADA-713]...10.69.212.21[10.69.212.21]
Mar 28 09:52:40.111711 info CLA-0 charon: 11[IKE] sending DELETE for IKE_SA r1cmptun~cmptun[1]
Mar 28 09:52:40.117719 info CLA-0 charon: 12[IKE] IKE_SA deleted
Mar 28 09:52:40.117816 info CLA-0 charon: 12[IKE] initiating IKE_SA r1cmptun~cmptun[2] to 10.69.212.21
Mar 28 09:52:40.118630 info CLA-0 FPM[766]: fpm_ipsec_sa_delete:
Mar 28 09:52:40.118806 info CLA-0 FPM[766]: del SA success
Mar 28 09:52:40.119007 info CLA-0 FPM[766]: fpm_ipsec_sa_delete:
Mar 28 09:52:40.119214 info CLA-0 FPM[766]: del SA success
Mar 28 09:52:40.119398 info CLA-0 FPM[766]: fpm_ipsec_sp_delete:
Mar 28 09:52:40.119672 info CLA-0 FPM[766]: del SP success
Mar 28 09:52:40.119883 info CLA-0 FPM[766]: fpm_ipsec_sp_delete:
Mar 28 09:52:40.120058 info CLA-0 FPM[766]: del SP success
Mar 28 09:52:40.127179 info CLA-0 charon: 13[IKE] received cert request for "C=FI, O=NSN, CN=MRTAmpereNewRootCA"
Mar 28 09:52:40.127455 info CLA-0 charon: 13[IKE] sending cert request for "C=FI, O=NSN, CN=MRTAmpereNewRootCA"
Mar 28 09:52:40.164732 info CLA-0 charon: 13[IKE] authentication of 'C=FI, O=NSN, OU=SyVe, CN=IADA-713' (myself) with RSA signature successful
Mar 28 09:52:40.164981 info CLA-0 charon: 13[IKE] sending end entity cert "C=FI, O=NSN, OU=SyVe, CN=IADA-713"
Mar 28 09:52:40.165100 info CLA-0 charon: 13[IKE] establishing CHILD_SA r1cmptun~cmptun
Mar 28 09:52:40.198760 info CLA-0 charon: 15[IKE] received end entity cert "C=China, OU=DEV, CN=Syve-test"
Mar 28 09:52:40.199019 info CLA-0 charon: 15[CFG] using certificate "C=China, OU=DEV, CN=Syve-test"
Mar 28 09:52:40.199199 info CLA-0 charon: 15[CFG] using trusted ca certificate "C=FI, O=NSN, CN=MRTAmpereNewRootCA"
Mar 28 09:52:40.199390 info CLA-0 charon: 15[CFG] checking certificate status of "C=China, OU=DEV, CN=Syve-test"
Mar 28 09:52:40.199594 info CLA-0 charon: 15[CFG] certificate status is not available
Mar 28 09:52:40.200285 info CLA-0 charon: 15[IKE] authentication of '10.69.212.21' with RSA signature successful
Mar 28 09:52:40.200465 info CLA-0 charon: 15[IKE] scheduling reauthentication in 562s
Mar 28 09:52:40.200756 info CLA-0 charon: 15[IKE] maximum IKE_SA lifetime 592s
Mar 28 09:52:40.201063 info CLA-0 charon: 15[IKE] IKE_SA r1cmptun~cmptun[2] established between 10.69.200.89[C=FI, O=NSN, OU=SyVe, CN=IADA-713]...10.69.212.21[10.69.212.21]
Mar 28 09:52:40.202315 info CLA-0 FPM[766]: fpm_ipsec_sa_create:
Mar 28 09:52:40.202492 info CLA-0 FPM[766]: add SA success
Mar 28 09:52:40.203063 info CLA-0 FPM[766]: fpm_ipsec_sa_create:
Mar 28 09:52:40.203264 info CLA-0 FPM[766]: add SA success
Mar 28 09:52:40.203770 info CLA-0 FPM[766]: add SP success
Mar 28 09:52:40.204234 info CLA-0 FPM[766]: add SP success

3) First CHILD_SA created after rekeying of the IKE_SA [please observe the name r1cmptun~cmptun{2}]

Mar 28 09:52:40.289133 info CLA-0 charon: 15[IKE] CHILD_SA r1cmptun~cmptun{2} established with SPIs c273fa73_i 9bbb6d95_o and TS 192.168.0.0/16[0] === 10.0.0.0/8[0] 

4) This follows with the creation of CHILD_SA r1cmptun~cmptun{1} [please observe the name r1cmptun~cmptun{1}]

Mar 28 09:52:40.332415 info CLA-0 charon: 15[IKE] establishing CHILD_SA r1cmptun~cmptun{1}
Mar 28 09:52:40.341764 info CLA-0 FPM[766]: fpm_ipsec_sa_create:
Mar 28 09:52:40.341959 info CLA-0 FPM[766]: add SA success
Mar 28 09:52:40.342507 info CLA-0 FPM[766]: fpm_ipsec_sa_create:
Mar 28 09:52:40.342708 info CLA-0 FPM[766]: add SA success
Mar 28 09:52:40.343304 info CLA-0 FPM[766]: add SP success
Mar 28 09:52:40.343782 info CLA-0 FPM[766]: add SP success
Mar 28 09:52:40.431088 info CLA-0 charon: 07[IKE] CHILD_SA r1cmptun~cmptun{1} established with SPIs c4ba1f7c_i 4b34ea34_o and TS 192.168.0.0/16[0] === 10.0.0.0/8[0]

As per our understanding this new CHILD_SA with identifier {1} should not be created at all.

Thanks and Regards,
Anurag Ghosh

________________________________

From: ext Tobias Brunner [mailto:tobias at strongswan.org]
Sent: Fri 3/30/2012 8:22 PM
To: Ghosh, Anurag (EXT-Aricent - IN)
Cc: users at lists.strongswan.org; jyoti.singh at aricent.com; Agarwal, Nupur (EXT-Aricent - US); Dharwadkar, Sriram (NSN - IN/Bangalore)
Subject: Re: Reporting Issue:Old CHILD_SA not getting cleared

Hi Anurag,

> 1)      We are using StrongSwan charon [Linux strongSwan 4.3.1]

Just let me tell you that we don't really like to support such old
releases.  It would great if you could try if this issue is still
present in 4.6.2.

> 3)      After around 600 sec. from the start, IKE_SA re-keying
> starts, but just before that we observe that an INFORMATIONAL message
> (with Next Payload: Delete) is sent from NODE A to NODE B. Is this
> expected even before the IKE_SA re-keying starts? Moreover NODE B
> responds back with an INFORMATIONAL message (with Next Payload:
> None). This is expected only when IKE_SA re-keying happens and old
> IKE_SA's delete message is sent.

Well, my guess is (without config it's hard to tell) that you have set
reauth=yes (which is the default) in your config.  Then this is
perfectly normal.  The previous IKE_SA is deleted and the new one is
established from scratch.  Setting reauth=no will cause charon to do a
regular rekeying.

> 4)      After the IKE_SA re-keying is over and new IKE_SA is created,
> we observe that 2 new CHILD_SA's are created even though before the
> re-keying period the IKE_SA had only 1 CHILD_SA. Now both these
> CHILD_SAs work independently and re-keying independently. So after
> the end of 1st IKE_SA re-keying we have 2 CHILD_SAs even though we
> started with 1. The output of setkey -D also confirms the same.

This might be a bug with reauthentication in 4.3.1.  Try a newer release
to verify if that's the case.

> This issue is not observed when both end of the tunnel, i.e., NODE A
> and NODE B have StrongSwan charon. We suspect that this could be an
> interoperability issue. Can you please help us in debugging this
> issue?

That's interesting, but it's hard to tell, without logs, what exactly
the differences between both of these cases are.  Comparing the logs
might give you some clue why it's not an issue between two hosts running
charon.

Regards,
Tobias