[strongSwan] Charon and kernel out-of-sync

Mike Spengler mks at foobox.com
Thu Mar 3 06:59:17 CET 2011 

Hi,

I'm having a problem where the kernel policies and charons trap list are getting out of
sync (strongswan 4.5.1). It's occuring on a host-host transport connection when the
connection does an IKE_REAUTH task with an existing child SA. The kernel policy's reqid
is getting incremented, but the trap list entry is unchanged. Thus when a later XFRM
acquire comes in with the new reqid, it doesn't find a match on the trap list.

I don't know whether the charon reqid should be getting incremented for a reauth or
whether the policies need to be deleted and readded with the updated reqid. It's easy
for me to recreate, so I can test any fixes or gather more debug if needed.

Thanks for any help.
-mike


The scenario is:
         HOST 1                                HOST 2
                  <establish ike connection>
                       <establish SA (reqid=1)>
			  .
			  .
			  .
			  .
                                              <ike lifetime expires - IKE_REAUTH>
                   <new ike connection>
                       <new SA (reqid=2)>
			  .
			  .
			  .
  <reboot host 1>
                                              <SA deleted>
  <host 1 up>
                                              <ping6 host1>
                                                    XFRM acquire reqid=2
							-> no match


This is HOST-2's ipsec.conf. HOST-1 is the same (with left/right flipped).
config setup
         dumpdir=
         strictcrlpolicy=no
         uniqueids=yes
         plutostart=no
         charonstart=yes
conn %default
         auth=esp
         auto=route
         dpdaction=hold
         keyexchange=ikev2
         leftfirewall=no
         mobike=no
conn Policy_S0P0ipsec0sa0
         esp=3des-sha1!
         ike=3des-sha1-modp1024!
         ikelifetime=3600s
         keylife=1800s
         rekey=yes
         type=transport
         left=fd70:c154:c2df:83:2c0:ddff:fe12:cdd4
         right=fd70:c154:c2df:83:2c0:ddff:fe0d:53e6
         leftauth=psk
         rightauth=psk

Here's some data from HOST-2 after the problem has occurred:

[root at hsb3800-2 conf]# ip x m
acquire proto esp
   sel src fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 dst fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 proto ipv6-icmp type 128 code 0
   policy src fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 dst fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128
         dir out priority 1027 ptype main
         tmpl src :: dst ::
                 proto esp reqid 2 mode transport


[root at hsb3800-2 TRAP2]# ipsec statusall
Status of IKEv2 charon daemon (strongSwan 4.5.1):
   uptime: 104 minutes, since Mar 02 23:05:35 2011
   malloc: sbrk 151552, mmap 0, used 83064, free 68488
   worker threads: 1 idle of 8, job queue load: 0, scheduled events: 0
   loaded plugins: aes des sha1 sha2 md5 random x509 revocation constraints pubkey pkcs1 pgp pem fips-prf gmp xcbc hmac ctr kernel-netlink socket-default stroke
Listening IP addresses:
   10.20.83.97
   fd70:c154:c2df:83:2c0:ddff:fe12:cdd4
Connections:
Policy_S0P0ipsec0sa0:  fd70:c154:c2df:83:2c0:ddff:fe12:cdd4...fd70:c154:c2df:83:2c0:ddff:fe0d:53e6, dpddelay=30s
Policy_S0P0ipsec0sa0:   local:  [fd70:c154:c2df:83:2c0:ddff:fe12:cdd4] uses pre-shared key authentication
Policy_S0P0ipsec0sa0:   remote: [fd70:c154:c2df:83:2c0:ddff:fe0d:53e6] uses pre-shared key authentication
Policy_S0P0ipsec0sa0:   child:  dynamic === dynamic , dpdaction=hold
Routed Connections:
Policy_S0P0ipsec0sa0{1}:  ROUTED, TRANSPORT
Policy_S0P0ipsec0sa0{1}:   fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 === fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128
Security Associations:
   none

[root at hsb3800-2 TRAP2]# ip x p
src fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 dst fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128
         dir in priority 1027 ptype main
         tmpl src :: dst ::
                 proto esp reqid 2 mode transport
src fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 dst fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128
         dir out priority 1027 ptype main
         tmpl src :: dst ::
                 proto esp reqid 2 mode transport

logfile (w/ a few extra DBG's added)
-------
Mar  2 23:48:50 switch charon: 08[JOB] got event, queuing job for execution
Mar  2 23:48:50 switch charon: 08[JOB] next event in 14s 512ms, waiting
Mar  2 23:48:50 switch charon: 07[MGR] checkout IKE_SA
Mar  2 23:48:50 switch charon: 07[MGR] IKE_SA Policy_S0P0ipsec0sa0[1] successfully checked out
Mar  2 23:48:50 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|1> reauth.1490:
Mar  2 23:48:50 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|1> queueing IKE_REAUTH task
Mar  2 23:48:50 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|1> activating new tasks
Mar  2 23:48:50 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|1>   activating IKE_REAUTH task
Mar  2 23:48:50 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|1> deleting IKE_SA Policy_S0P0ipsec0sa0[1] between 
fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[fd70:c154:c2df:83:2c0:ddff:fe12:cdd4]...fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[fd70:c154:c2df:83:2c0:ddff:fe0d:53e6]
Mar  2 23:48:50 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|1> IKE_SA Policy_S0P0ipsec0sa0[1] state change: ESTABLISHED => DELETING
Mar  2 23:48:50 switch charon: 08[JOB] next event in 14s 473ms, waiting
Mar  2 23:48:50 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|1> sending DELETE for IKE_SA Policy_S0P0ipsec0sa0[1]
Mar  2 23:48:50 switch charon: 07[ENC] <Policy_S0P0ipsec0sa0|1> generating INFORMATIONAL request 12 [ D ]
Mar  2 23:48:50 switch charon: 07[NET] <Policy_S0P0ipsec0sa0|1> sending packet: from fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500] to fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500]
Mar  2 23:48:50 switch charon: 08[JOB] next event in 3s 999ms, waiting
Mar  2 23:48:50 switch charon: 07[MGR] <Policy_S0P0ipsec0sa0|1> checkin IKE_SA Policy_S0P0ipsec0sa0[1]
Mar  2 23:48:50 switch charon: 07[MGR] <Policy_S0P0ipsec0sa0|1> check-in of IKE_SA successful.
Mar  2 23:48:50 switch charon: 04[NET] sending packet: from fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500] to fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500]
Mar  2 23:48:50 switch charon: 05[NET] received packet: from fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500] to fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500]
Mar  2 23:48:50 switch charon: 05[NET] waiting for data on sockets
Mar  2 23:48:50 switch charon: 06[MGR] checkout IKE_SA by message
Mar  2 23:48:50 switch charon: 06[MGR] IKE_SA Policy_S0P0ipsec0sa0[1] successfully checked out
Mar  2 23:48:50 switch charon: 06[NET] <Policy_S0P0ipsec0sa0|1> received packet: from fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500] to fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500]
Mar  2 23:48:50 switch charon: 06[ENC] <Policy_S0P0ipsec0sa0|1> parsed INFORMATIONAL response 12 [ ]
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> update_hosts.833:
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> IKE_SA deleted
Mar  2 23:48:50 switch charon: 06[MGR] <Policy_S0P0ipsec0sa0|1> created IKE_SA (unnamed)[2]
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> initiate.1097:
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> queueing IKE_VENDOR task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> queueing IKE_INIT task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> queueing IKE_NATD task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> queueing IKE_CERT_PRE task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> queueing IKE_AUTHENTICATE task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> queueing IKE_CERT_POST task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> queueing IKE_CONFIG task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> queueing IKE_AUTH_LIFETIME task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> queueing CHILD_CREATE task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> activating new tasks
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1>   activating IKE_VENDOR task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1>   activating IKE_INIT task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1>   activating IKE_NATD task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1>   activating IKE_CERT_PRE task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1>   activating IKE_AUTHENTICATE task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1>   activating IKE_CERT_POST task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1>   activating IKE_CONFIG task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1>   activating CHILD_CREATE task
Mar  2 23:48:50 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1>   activating IKE_AUTH_LIFETIME task
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> initiating IKE_SA Policy_S0P0ipsec0sa0[2] to fd70:c154:c2df:83:2c0:ddff:fe0d:53e6
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> IKE_SA Policy_S0P0ipsec0sa0[2] state change: CREATED => CONNECTING
Mar  2 23:48:51 switch charon: 06[LIB] <Policy_S0P0ipsec0sa0|1> size of DH secret exponent: 1022 bits
Mar  2 23:48:51 switch charon: 06[ENC] <Policy_S0P0ipsec0sa0|1> generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
Mar  2 23:48:51 switch charon: 06[NET] <Policy_S0P0ipsec0sa0|1> sending packet: from fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500] to fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500]
Mar  2 23:48:51 switch charon: 04[NET] sending packet: from fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500] to fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500]
Mar  2 23:48:51 switch charon: 08[JOB] next event in 3s 710ms, waiting
Mar  2 23:48:51 switch charon: 06[MGR] <Policy_S0P0ipsec0sa0|1> checkin IKE_SA Policy_S0P0ipsec0sa0[2]
Mar  2 23:48:51 switch charon: 06[MGR] <Policy_S0P0ipsec0sa0|1> checkin and destroy IKE_SA Policy_S0P0ipsec0sa0[1]
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> destroy.1996:
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|1> IKE_SA Policy_S0P0ipsec0sa0[1] state change: DELETING => DESTROYING
Mar  2 23:48:51 switch charon: 06[CHD] <Policy_S0P0ipsec0sa0|1> destroy.915:
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|1> deleting SAD entry with SPI c698b6c8
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|1> deleted SAD entry with SPI c698b6c8
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|1> deleting SAD entry with SPI c0daf98b
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|1> deleted SAD entry with SPI c0daf98b
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|1> deleting policy fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 === fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 out
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|1> policy still used by another CHILD_SA, not removed
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|1> deleting policy fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 === fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 in
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|1> policy still used by another CHILD_SA, not removed
Mar  2 23:48:51 switch charon: 06[MGR] check-in and destroy of IKE_SA successful
Mar  2 23:48:51 switch charon: 05[NET] received packet: from fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500] to fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500]
Mar  2 23:48:51 switch charon: 05[NET] waiting for data on sockets
Mar  2 23:48:51 switch charon: 07[MGR] checkout IKE_SA by message
Mar  2 23:48:51 switch charon: 07[MGR] IKE_SA Policy_S0P0ipsec0sa0[2] successfully checked out
Mar  2 23:48:51 switch charon: 07[NET] <Policy_S0P0ipsec0sa0|2> received packet: from fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500] to fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500]
Mar  2 23:48:51 switch charon: 07[ENC] <Policy_S0P0ipsec0sa0|2> parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(MULT_AUTH) ]
Mar  2 23:48:51 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|2> update_hosts.833:
Mar  2 23:48:51 switch charon: 07[CFG] <Policy_S0P0ipsec0sa0|2> selecting proposal:
Mar  2 23:48:51 switch charon: 07[CFG] <Policy_S0P0ipsec0sa0|2>   proposal matches
Mar  2 23:48:51 switch charon: 07[CFG] <Policy_S0P0ipsec0sa0|2> received proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Mar  2 23:48:51 switch charon: 07[CFG] <Policy_S0P0ipsec0sa0|2> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Mar  2 23:48:51 switch charon: 07[CFG] <Policy_S0P0ipsec0sa0|2> selected proposal: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Mar  2 23:48:51 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|2> reinitiating already active tasks
Mar  2 23:48:51 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|2>   IKE_CERT_PRE task
Mar  2 23:48:51 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|2>   IKE_AUTHENTICATE task
Mar  2 23:48:51 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|2> authentication of 'fd70:c154:c2df:83:2c0:ddff:fe12:cdd4' (myself) with pre-shared key
Mar  2 23:48:51 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|2> successfully created shared key MAC
Mar  2 23:48:51 switch charon: 07[IKE] <Policy_S0P0ipsec0sa0|2> establishing CHILD_SA Policy_S0P0ipsec0sa0
Mar  2 23:48:51 switch charon: 07[CFG] <Policy_S0P0ipsec0sa0|2> proposing traffic selectors for us:
Mar  2 23:48:51 switch charon: 07[CFG] <Policy_S0P0ipsec0sa0|2>  fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 (derived from dynamic)
Mar  2 23:48:51 switch charon: 07[CFG] <Policy_S0P0ipsec0sa0|2> proposing traffic selectors for other:
Mar  2 23:48:51 switch charon: 07[CFG] <Policy_S0P0ipsec0sa0|2>  fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 (derived from dynamic)
Mar  2 23:48:51 switch charon: 07[CHD] <Policy_S0P0ipsec0sa0|2> child_sa_create.1029: reqid=0 rekey=0 reqid=1
Mar  2 23:48:51 switch charon: 07[KNL] <Policy_S0P0ipsec0sa0|2> getting SPI for reqid {2}
Mar  2 23:48:51 switch charon: 07[KNL] <Policy_S0P0ipsec0sa0|2> got SPI cb48d316 for reqid {2}
Mar  2 23:48:51 switch charon: 07[ENC] <Policy_S0P0ipsec0sa0|2> generating IKE_AUTH request 1 [ IDi CERTREQ IDr AUTH N(USE_TRANSP) SA TSi TSr N(MULT_AUTH) N(EAP_ONLY) ]
Mar  2 23:48:51 switch charon: 07[NET] <Policy_S0P0ipsec0sa0|2> sending packet: from fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500] to fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500]
Mar  2 23:48:51 switch charon: 04[NET] sending packet: from fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500] to fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500]
Mar  2 23:48:51 switch charon: 08[JOB] next event in 3s 394ms, waiting
Mar  2 23:48:51 switch charon: 07[MGR] <Policy_S0P0ipsec0sa0|2> checkin IKE_SA Policy_S0P0ipsec0sa0[2]
Mar  2 23:48:51 switch charon: 07[MGR] <Policy_S0P0ipsec0sa0|2> check-in of IKE_SA successful.
Mar  2 23:48:51 switch charon: 05[NET] received packet: from fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500] to fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500]
Mar  2 23:48:51 switch charon: 05[NET] waiting for data on sockets
Mar  2 23:48:51 switch charon: 06[MGR] checkout IKE_SA by message
Mar  2 23:48:51 switch charon: 06[MGR] IKE_SA Policy_S0P0ipsec0sa0[2] successfully checked out
Mar  2 23:48:51 switch charon: 06[NET] <Policy_S0P0ipsec0sa0|2> received packet: from fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500] to fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500]
Mar  2 23:48:51 switch charon: 06[ENC] <Policy_S0P0ipsec0sa0|2> parsed IKE_AUTH response 1 [ IDr AUTH N(USE_TRANSP) SA TSi TSr N(AUTH_LFT) ]
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> update_hosts.833:
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> received USE_TRANSPORT_MODE notify
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> authentication of 'fd70:c154:c2df:83:2c0:ddff:fe0d:53e6' with pre-shared key successful
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> IKE_SA Policy_S0P0ipsec0sa0[2] established between 
fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[fd70:c154:c2df:83:2c0:ddff:fe12:cdd4]...fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[fd70:c154:c2df:83:2c0:ddff:fe0d:53e6]
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> IKE_SA Policy_S0P0ipsec0sa0[2] state change: CONNECTING => ESTABLISHED
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> scheduling reauthentication in 2912s
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> maximum IKE_SA lifetime 3452s
Mar  2 23:48:51 switch charon: 06[CFG] <Policy_S0P0ipsec0sa0|2> selecting proposal:
Mar  2 23:48:51 switch charon: 06[CFG] <Policy_S0P0ipsec0sa0|2>   proposal matches
Mar  2 23:48:51 switch charon: 06[CFG] <Policy_S0P0ipsec0sa0|2> received proposals: ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
Mar  2 23:48:51 switch charon: 06[CFG] <Policy_S0P0ipsec0sa0|2> configured proposals: ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
Mar  2 23:48:51 switch charon: 06[CFG] <Policy_S0P0ipsec0sa0|2> selected proposal: ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
Mar  2 23:48:51 switch charon: 06[CFG] <Policy_S0P0ipsec0sa0|2> selecting traffic selectors for us:
Mar  2 23:48:51 switch charon: 06[CFG] <Policy_S0P0ipsec0sa0|2>  config: fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128, received: fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 => match: 
fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128
Mar  2 23:48:51 switch charon: 06[CFG] <Policy_S0P0ipsec0sa0|2> selecting traffic selectors for other:
Mar  2 23:48:51 switch charon: 06[CFG] <Policy_S0P0ipsec0sa0|2>  config: fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128, received: fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 => match: 
fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128
Mar  2 23:48:51 switch charon: 06[CHD] <Policy_S0P0ipsec0sa0|2>   using 3DES_CBC for encryption
Mar  2 23:48:51 switch charon: 06[CHD] <Policy_S0P0ipsec0sa0|2>   using HMAC_SHA1_96 for integrity
Mar  2 23:48:51 switch charon: 06[CHD] <Policy_S0P0ipsec0sa0|2> adding inbound ESP SA
Mar  2 23:48:51 switch charon: 06[CHD] <Policy_S0P0ipsec0sa0|2>   SPI 0xcb48d316, src fd70:c154:c2df:83:2c0:ddff:fe0d:53e6 dst fd70:c154:c2df:83:2c0:ddff:fe12:cdd4
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> adding SAD entry with SPI cb48d316 and reqid {2}
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2>   using encryption algorithm 3DES_CBC with key size 192
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2>   using integrity algorithm HMAC_SHA1_96 with key size 160
Mar  2 23:48:51 switch charon: 06[CHD] <Policy_S0P0ipsec0sa0|2> adding outbound ESP SA
Mar  2 23:48:51 switch charon: 06[CHD] <Policy_S0P0ipsec0sa0|2>   SPI 0xcedd9e58, src fd70:c154:c2df:83:2c0:ddff:fe12:cdd4 dst fd70:c154:c2df:83:2c0:ddff:fe0d:53e6
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> adding SAD entry with SPI cedd9e58 and reqid {2}
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2>   using encryption algorithm 3DES_CBC with key size 192
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2>   using integrity algorithm HMAC_SHA1_96 with key size 160
Mar  2 23:48:51 switch charon: 06[CHD] <Policy_S0P0ipsec0sa0|2> add_policies.666:
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> policy fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 === fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 out already exists, increasing refcount
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> adding policy fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 === fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 out
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> policy fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 === fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 in already exists, increasing refcount
Mar  2 23:48:51 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> adding policy fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 === fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 in
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> CHILD_SA Policy_S0P0ipsec0sa0{2} established with SPIs cb48d316_i cedd9e58_o and TS fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 === 
fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> received AUTH_LIFETIME of 2660s, scheduling reauthentication in 2120s
Mar  2 23:48:51 switch charon: 08[JOB] next event in 3s 96ms, waiting
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> activating new tasks
Mar  2 23:48:51 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> nothing to initiate
Mar  2 23:48:51 switch charon: 06[MGR] <Policy_S0P0ipsec0sa0|2> checkin IKE_SA Policy_S0P0ipsec0sa0[2]
Mar  2 23:48:51 switch charon: 06[MGR] <Policy_S0P0ipsec0sa0|2> check-in of IKE_SA successful.


<HOST-1 is rebooted here>


Mar  2 23:56:37 switch charon: 05[NET] received packet: from fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500] to fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500]
Mar  2 23:56:37 switch charon: 06[MGR] checkout IKE_SA by message
Mar  2 23:56:37 switch charon: 06[MGR] IKE_SA Policy_S0P0ipsec0sa0[2] successfully checked out
Mar  2 23:56:37 switch charon: 06[NET] <Policy_S0P0ipsec0sa0|2> received packet: from fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500] to fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500]
Mar  2 23:56:37 switch charon: 06[ENC] <Policy_S0P0ipsec0sa0|2> parsed INFORMATIONAL request 15 [ D ]
Mar  2 23:56:37 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> update_hosts.833:
Mar  2 23:56:37 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> received DELETE for IKE_SA Policy_S0P0ipsec0sa0[2]
Mar  2 23:56:37 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> deleting IKE_SA Policy_S0P0ipsec0sa0[2] between 
fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[fd70:c154:c2df:83:2c0:ddff:fe12:cdd4]...fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[fd70:c154:c2df:83:2c0:ddff:fe0d:53e6]
Mar  2 23:56:37 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> IKE_SA Policy_S0P0ipsec0sa0[2] state change: ESTABLISHED => DELETING
Mar  2 23:56:37 switch charon: 08[JOB] next event in 13s 727ms, waiting
Mar  2 23:56:37 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> reestablish.1534:
Mar  2 23:56:37 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> reestablish.1547: state=5 action=1
Mar  2 23:56:37 switch charon: 06[CFG] <Policy_S0P0ipsec0sa0|2> CHILD_SA named 'Policy_S0P0ipsec0sa0' already routed
Mar  2 23:56:37 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> IKE_SA deleted
Mar  2 23:56:37 switch charon: 06[ENC] <Policy_S0P0ipsec0sa0|2> generating INFORMATIONAL response 15 [ ]
Mar  2 23:56:37 switch charon: 06[NET] <Policy_S0P0ipsec0sa0|2> sending packet: from fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500] to fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500]
Mar  2 23:56:37 switch charon: 06[MGR] <Policy_S0P0ipsec0sa0|2> checkin and destroy IKE_SA Policy_S0P0ipsec0sa0[2]
Mar  2 23:56:37 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> destroy.1996:
Mar  2 23:56:37 switch charon: 06[IKE] <Policy_S0P0ipsec0sa0|2> IKE_SA Policy_S0P0ipsec0sa0[2] state change: DELETING => DESTROYING
Mar  2 23:56:37 switch charon: 06[CHD] <Policy_S0P0ipsec0sa0|2> destroy.915:
Mar  2 23:56:37 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> deleting SAD entry with SPI cb48d316
Mar  2 23:56:37 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> deleted SAD entry with SPI cb48d316
Mar  2 23:56:37 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> deleting SAD entry with SPI cedd9e58
Mar  2 23:56:37 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> deleted SAD entry with SPI cedd9e58
Mar  2 23:56:37 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> deleting policy fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 === fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 out
Mar  2 23:56:37 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> policy still used by another CHILD_SA, not removed
Mar  2 23:56:37 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> deleting policy fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128 === fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128 in
Mar  2 23:56:37 switch charon: 06[KNL] <Policy_S0P0ipsec0sa0|2> policy still used by another CHILD_SA, not removed
Mar  2 23:56:37 switch charon: 06[MGR] check-in and destroy of IKE_SA successful
Mar  2 23:56:37 switch charon: 04[NET] sending packet: from fd70:c154:c2df:83:2c0:ddff:fe12:cdd4[500] to fd70:c154:c2df:83:2c0:ddff:fe0d:53e6[500]
Mar  2 23:56:37 switch charon: 05[NET] waiting for data on sockets
Mar  2 23:56:50 switch charon: 08[JOB] got event, queuing job for execution
Mar  2 23:56:50 switch charon: 08[JOB] next event in 16s 271ms, waiting
Mar  2 23:56:50 switch charon: 07[MGR] checkout IKE_SA
Mar  2 23:56:57 switch charon: 06[CFG] proposing traffic selectors for us:
Mar  2 23:56:57 switch charon: 06[CFG]  dynamic (derived from dynamic)
Mar  2 23:56:57 switch charon: 06[CFG] proposing traffic selectors for other:
Mar  2 23:56:57 switch charon: 06[CFG]  dynamic (derived from dynamic)
Mar  2 23:57:07 switch charon: 08[JOB] got event, queuing job for execution
Mar  2 23:57:07 switch charon: 06[MGR] checkout IKE_SA
Mar  2 23:57:07 switch charon: 08[JOB] next event in 188s 339ms, waiting
Mar  2 23:59:09 switch charon: 06[CFG] proposing traffic selectors for us:
Mar  2 23:59:09 switch charon: 06[CFG]  dynamic (derived from dynamic)
Mar  2 23:59:09 switch charon: 06[CFG] proposing traffic selectors for other:
Mar  2 23:59:09 switch charon: 06[CFG]  dynamic (derived from dynamic)


<ping6 from HOST-2 to HOST-1>


Mar  2 23:59:23 switch charon: 01[KNL] received a XFRM_MSG_ACQUIRE
Mar  2 23:59:23 switch charon: 01[KNL]   XFRMA_TMPL
Mar  2 23:59:23 switch charon: 01[KNL] creating acquire job for policy fd70:c154:c2df:83:2c0:ddff:fe12:cdd4/128[ipv6-icmp/128] === fd70:c154:c2df:83:2c0:ddff:fe0d:53e6/128[ipv6-icmp] with reqid {2}
Mar  2 23:59:23 switch charon: 03[CFG] acquiring trap: request reqid=2; entry: name=Policy_S0P0ipsec0sa0 reqid=1
Mar  2 23:59:23 switch charon: 03[CFG] trap not found, unable to acquire reqid 2
Mar  3 00:00:15 switch charon: 08[JOB] got event, queuing job for execution
Mar  3 00:00:15 switch charon: 08[JOB] next event in 539s 991ms, waiting
Mar  3 00:00:15 switch charon: 07[MGR] checkout IKE_SA
Mar  3 00:00:15 switch charon: 07[JOB] IKE_SA to rekey not found

More information about the Users mailing list