[strongSwan] Tunnel going down after 40+ hours

Fri Oct 11 21:39:43 CEST 2019

Hello everyone,

We are running Strongswan 5.8 on Linux:
Linux t1024rdb 4.1.35-rt41 #1 SMP PREEMPT Wed Sep 4 14:39:22 EDT 2019 ppc64 GNU/Linux

The tunnel is set up and works great for nearly 41 hours and then it is destroyed. We have experienced the same failure 2 consecutive times. So we increased the log level and dumped NET, ENC, IKE, CFG and KNL log levels.

We notice that when we fail we get an XFRM_MSG_EXPIRE. After that we do not receive a response from the other side and then we give up after 5 attempts. In previous XFRM_MSG_EXPIRE instances we notice that replies were received from the other side.

The IP connectivity between both the machines is up. Also the next time we "ipsec start" the tunnels are set up correctly and start working again.

We were wondering if someone can comment/speculate on possible reasons for the failure? 

Any way we can instruct charon to retry after giving up?

Your thoughts/suggestions would be highly appreciated.

Logs below:

ct  6 05:33:59 t1024rdb charon: 16[NET] received packet: from 80.0.0.1[500] to 80.0.0.2[500] (392 bytes)
Oct  6 05:33:59 t1024rdb charon: 16[ENC] parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
Oct  6 05:33:59 t1024rdb charon: 16[IKE] 80.0.0.1 is initiating an IKE_SA
Oct  6 05:33:59 t1024rdb charon: 16[CFG] selected proposal: IKE:AES_CBC_128/HMAC_SHA2_256_128/PRF_AES128_XCBC/CURVE_25519
Oct  6 05:33:59 t1024rdb charon: 16[ENC] generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(CHDLESS_SUP) N(MULT_AUTH) ]
Oct  6 05:33:59 t1024rdb charon: 16[NET] sending packet: from 80.0.0.2[500] to 80.0.0.1[500] (248 bytes)
Oct  6 05:34:00 t1024rdb charon: 09[NET] received packet: from 80.0.0.1[4500] to 80.0.0.2[4500] (368 bytes)
Oct  6 05:34:00 t1024rdb charon: 09[ENC] parsed IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(ADD_4_ADDR) N(MULT_AUTH) N(EAP_ONLY) N(MSG_ID_SYN_SUP) ]
Oct  6 05:34:00 t1024rdb charon: 09[CFG] looking for peer configs matching 80.0.0.2[80.0.0.2]...80.0.0.1[80.0.0.1]
Oct  6 05:34:00 t1024rdb charon: 09[CFG] selected peer config 'pi_to_pi'
Oct  6 05:34:00 t1024rdb charon: 09[IKE] authentication of '80.0.0.1' with pre-shared key successful
Oct  6 05:34:00 t1024rdb charon: 09[IKE] peer supports MOBIKE
Oct  6 05:34:00 t1024rdb charon: 09[IKE] authentication of '80.0.0.2' (myself) with pre-shared key
Oct  6 05:34:00 t1024rdb charon: 09[IKE] IKE_SA pi_to_pi[15] established between 80.0.0.2[80.0.0.2]...80.0.0.1[80.0.0.1]
Oct  6 05:34:00 t1024rdb charon: 09[IKE] scheduling reauthentication in 9851s
Oct  6 05:34:00 t1024rdb charon: 09[IKE] maximum IKE_SA lifetime 10391s
Oct  6 05:34:00 t1024rdb charon: 09[CFG] selected proposal: ESP:AES_CBC_128/HMAC_SHA2_256_128/NO_EXT_SEQ
Oct  6 05:34:00 t1024rdb charon: 09[IKE] CHILD_SA pi_to_pi{56} established with SPIs cea7040d_i c0677e95_o and TS 192.168.2.0/24 192.168.55.0/24 === 192.168.1.0/24
Oct  6 05:34:00 t1024rdb charon: 09[ENC] generating IKE_AUTH response 1 [ IDr AUTH 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) ]

....

Oct  7 22:55:35 t1024rdb charon: 14[KNL] received a XFRM_MSG_EXPIRE
Oct  7 22:55:35 t1024rdb charon: 14[KNL] creating rekey job for CHILD_SA ESP/0xc540db84/80.0.0.2
Oct  7 22:55:35 t1024rdb charon: 14[IKE] queueing CHILD_REKEY task
Oct  7 22:55:35 t1024rdb charon: 14[IKE] activating new tasks
Oct  7 22:55:35 t1024rdb charon: 14[IKE]   activating CHILD_REKEY task
Oct  7 22:55:35 t1024rdb charon: 14[IKE] establishing CHILD_SA pi_to_pi{119} reqid 28
Oct  7 22:55:35 t1024rdb charon: 14[KNL] got SPI c9169901
Oct  7 22:55:35 t1024rdb charon: 14[CHD] CHILD_SA pi_to_pi{118} state change: INSTALLED => REKEYING
Oct  7 22:55:35 t1024rdb charon: 14[ENC] generating CREATE_CHILD_SA request 2 [ N(REKEY_SA) SA No TSi TSr ]
Oct  7 22:55:35 t1024rdb charon: 14[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500] (288 bytes)
Oct  7 22:55:35 t1024rdb charon: 03[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500]
Oct  7 22:55:39 t1024rdb charon: 04[IKE] retransmit 1 of request with message ID 2
Oct  7 22:55:39 t1024rdb charon: 04[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500] (288 bytes)
Oct  7 22:55:39 t1024rdb charon: 03[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500]
Oct  7 22:55:46 t1024rdb charon: 09[IKE] retransmit 2 of request with message ID 2
Oct  7 22:55:46 t1024rdb charon: 09[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500] (288 bytes)
Oct  7 22:55:46 t1024rdb charon: 03[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500]
Oct  7 22:55:59 t1024rdb charon: 07[IKE] retransmit 3 of request with message ID 2
Oct  7 22:55:59 t1024rdb charon: 07[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500] (288 bytes)
Oct  7 22:55:59 t1024rdb charon: 03[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500]
Oct  7 22:56:22 t1024rdb charon: 08[IKE] retransmit 4 of request with message ID 2
Oct  7 22:56:22 t1024rdb charon: 08[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500] (288 bytes)
Oct  7 22:56:22 t1024rdb charon: 03[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500]
Oct  7 22:57:04 t1024rdb charon: 11[IKE] retransmit 5 of request with message ID 2
Oct  7 22:57:04 t1024rdb charon: 11[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500] (288 bytes)
Oct  7 22:57:04 t1024rdb charon: 03[NET] sending packet: from 80.0.0.2[4500] to 80.0.0.1[4500]
Oct  7 22:57:35 t1024rdb charon: 16[KNL] received a XFRM_MSG_EXPIRE
Oct  7 22:57:35 t1024rdb charon: 16[KNL] creating rekey job for CHILD_SA ESP/0xce9c4468/80.0.0.1
Oct  7 22:57:35 t1024rdb charon: 16[IKE] queueing CHILD_REKEY task
Oct  7 22:57:35 t1024rdb charon: 16[IKE] delaying task initiation, CREATE_CHILD_SA exchange in progress
Oct  7 22:58:20 t1024rdb charon: 10[KNL] received a XFRM_MSG_EXPIRE
Oct  7 22:58:20 t1024rdb charon: 10[KNL] creating delete job for CHILD_SA ESP/0xc9169901/80.0.0.2
Oct  7 22:58:20 t1024rdb charon: 10[JOB] CHILD_SA ESP/0xc9169901/80.0.0.2 not found for delete
Oct  7 22:58:20 t1024rdb charon: 13[IKE] giving up after 5 retransmits
Oct  7 22:58:20 t1024rdb charon: 13[IKE] IKE_SA pi_to_pi[30] state change: ESTABLISHED => DESTROYING
Oct  7 22:58:20 t1024rdb charon: 13[CHD] CHILD_SA pi_to_pi{119} state change: CREATED => DESTROYING
Oct  7 22:58:20 t1024rdb charon: 13[KNL] deleting SAD entry with SPI c9169901
Oct  7 22:58:20 t1024rdb charon: 13[CHD] CHILD_SA pi_to_pi{118} state change: REKEYING => DESTROYING
Oct  7 22:58:20 t1024rdb charon: 13[KNL] deleting policy 192.168.2.0/24 === 192.168.1.0/24 out
Oct  7 22:58:20 t1024rdb charon: 13[KNL] getting iface index for fm1-mac1.0555
Oct  7 22:58:20 t1024rdb charon: 13[KNL] deleting policy 192.168.1.0/24 === 192.168.2.0/24 in
Oct  7 22:58:20 t1024rdb charon: 13[KNL] deleting policy 192.168.1.0/24 === 192.168.2.0/24 fwd
Oct  7 22:58:20 t1024rdb charon: 13[KNL] deleting policy 192.168.55.0/24 === 192.168.1.0/24 out

Makarand Pradhan
Senior Software Engineer.
iS5 Communications Inc.
#1-1815 Meyerside Drive
Mississauga, Ontario
L5T 1G3
Main Line: +1-844-520-0588 Ext. 129
Direct Line: +1-289-724-2296
Cell: +1-226-501-5666
Fax:+1-289-401-5206
Email: makarandpradhan at is5com.com
Website: www.iS5Com.com

Confidentiality Notice: 
This message is intended only for the named recipients. This message may contain information that is confidential and/or exempt from disclosure under applicable law. Any dissemination or copying of this message by anyone other than a named recipient is strictly prohibited. If you are not a named recipient or an employee or agent responsible for delivering this message to a named recipient, please notify us immediately, and permanently destroy this message and any copies you may have. Warning: Email may not be secure unless properly encrypted.