[strongSwan] Remote site dies for no reason?

Thu Oct 20 20:57:15 CEST 2022

Hi Rene,

With IKEv2 the global ikev2 timeouts are used.
Change charon.retransmit_base, charon.retransmit_jitter, charon.retransmit_limit, charon.retransmit_timeout, charon.retransmit_tries as required to achieve the desired timeout.
See https://docs.strongswan.org/docs/6.0/config/retransmission.html for details

Kind regards
Noel

On 20.10.22 10:45, Rene Maurer wrote:
> Hello
> 
> We are  using strongSwan U5.4.0/K4.4.107 (embedded device) and making an ipec connection to a remote CISCO system.
> 
>  From time to time we see the following behavior (tunnel seams to stop working):
> 
> ------------------------------------------------------------------------
> Oct 20 09:32:33 EGV charon[656]: 13[KNL] creating rekey job for CHILD_SA ESP/0xc5ff03b6/xx.xxx.xxx.xxx
> Oct 20 09:32:33 EGV charon[656]: 13[IKE] establishing CHILD_SA one{1}
> Oct 20 09:32:33 EGV charon[656]: 13[IKE] establishing CHILD_SA one{1}
> Oct 20 09:32:33 EGV charon[656]: 13[ENC] generating CREATE_CHILD_SA request 24388 [ N(REKEY_SA) SA No KE TSi TSr ]
> Oct 20 09:32:33 EGV charon[656]: 13[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (309 bytes)
> Oct 20 09:32:33 EGV charon[656]: 08[NET] received packet: from xx.xxx.xxx.xxx[4500] to 10.162.225.65[4500] (297 bytes)
> Oct 20 09:32:33 EGV charon[656]: 08[ENC] parsed CREATE_CHILD_SA response 24388 [ SA No KE TSi TSr ]
> Oct 20 09:32:33 EGV charon[656]: 08[IKE] CHILD_SA one{93} established with SPIs c70a8723_i a5e30c1d_o and TS 10.162.110.160/29 === 10.0.0.0/8
> Oct 20 09:32:33 EGV charon[656]: 08[IKE] CHILD_SA one{93} established with SPIs c70a8723_i a5e30c1d_o and TS 10.162.110.160/29 === 10.0.0.0/8
> Oct 20 09:32:33 EGV charon[656]: 08[IKE] closing CHILD_SA one{92} with SPIs ca335ba8_i (21496 bytes) c5ff03b6_o (21496 bytes) and TS 10.162.110.160/29 === 10.0.0.0/8
> Oct 20 09:32:33 EGV charon[656]: 08[IKE] closing CHILD_SA one{92} with SPIs ca335ba8_i (21496 bytes) c5ff03b6_o (21496 bytes) and TS 10.162.110.160/29 === 10.0.0.0/8
> Oct 20 09:32:33 EGV charon[656]: 08[IKE] sending DELETE for ESP CHILD_SA with SPI ca335ba8
> Oct 20 09:32:33 EGV charon[656]: 08[ENC] generating INFORMATIONAL request 24389 [ D ]
> Oct 20 09:32:33 EGV charon[656]: 08[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (69 bytes)
> Oct 20 09:32:33 EGV charon[656]: 14[NET] received packet: from xx.xxx.xxx.xxx[4500] to 10.162.225.65[4500] (69 bytes)
> Oct 20 09:32:33 EGV charon[656]: 14[ENC] parsed INFORMATIONAL response 24389 [ D ]
> Oct 20 09:32:33 EGV charon[656]: 14[IKE] received DELETE for ESP CHILD_SA with SPI c5ff03b6
> Oct 20 09:32:33 EGV charon[656]: 14[IKE] CHILD_SA closed
> Oct 20 09:32:37 EGV charon[656]: 10[IKE] sending DPD request
> Oct 20 09:32:37 EGV charon[656]: 10[ENC] generating INFORMATIONAL request 24390 [ ]
> Oct 20 09:32:37 EGV charon[656]: 10[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (57 bytes)
> Oct 20 09:32:37 EGV charon[656]: 16[NET] received packet: from xx.xxx.xxx.xxx[4500] to 10.162.225.65[4500] (57 bytes)
> Oct 20 09:32:37 EGV charon[656]: 16[ENC] parsed INFORMATIONAL response 24390 [ ]
> Oct 20 09:32:38 EGV charon[656]: 14[NET] received packet: from xx.xxx.xxx.xxx[4500] to 10.162.225.65[4500] (57 bytes)
> Oct 20 09:32:38 EGV charon[656]: 14[ENC] parsed INFORMATIONAL request 7089 [ ]
> Oct 20 09:32:38 EGV charon[656]: 14[ENC] generating INFORMATIONAL response 7089 [ ]
> Oct 20 09:32:38 EGV charon[656]: 14[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (57 bytes)
> Oct 20 09:32:40 EGV charon[656]: 08[IKE] sending DPD request
> Oct 20 09:32:40 EGV charon[656]: 08[ENC] generating INFORMATIONAL request 24391 [ ]
> Oct 20 09:32:40 EGV charon[656]: 08[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (57 bytes)
> Oct 20 09:32:40 EGV charon[656]: 06[NET] received packet: from xx.xxx.xxx.xxx[4500] to 10.162.225.65[4500] (57 bytes)
> Oct 20 09:32:40 EGV charon[656]: 06[ENC] parsed INFORMATIONAL response 24391 [ ]
> Oct 20 09:32:43 EGV charon[656]: 07[IKE] sending DPD request
> Oct 20 09:32:43 EGV charon[656]: 07[ENC] generating INFORMATIONAL request 24392 [ ]
> Oct 20 09:32:43 EGV charon[656]: 07[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (57 bytes)
> Oct 20 09:32:47 EGV charon[656]: 06[IKE] retransmit 1 of request with message ID 24392
> Oct 20 09:32:47 EGV charon[656]: 06[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (57 bytes)
> Oct 20 09:32:54 EGV charon[656]: 09[IKE] retransmit 2 of request with message ID 24392
> Oct 20 09:32:54 EGV charon[656]: 09[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (57 bytes)
> Ping::PingHost, send ping to xx.xxx.xxx.xxx, ret 8
> Ping::PingHost, ping reply received
> Oct 20 09:33:02 EGV charon[656]: 11[NET] received packet: from xx.xxx.xxx.xxx[4500] to 10.162.225.65[4500] (57 bytes)
> Oct 20 09:33:02 EGV charon[656]: 11[ENC] parsed INFORMATIONAL request 7090 [ ]
> Oct 20 09:33:02 EGV charon[656]: 11[ENC] generating INFORMATIONAL response 7090 [ ]
> Oct 20 09:33:02 EGV charon[656]: 11[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (57 bytes)
> Oct 20 09:33:02 EGV charon[656]: 13[MGR] ignoring request with ID 7090, already processing
> Oct 20 09:33:02 EGV charon[656]: 07[MGR] ignoring request with ID 7090, already processing
> Oct 20 09:33:02 EGV charon[656]: 07[MGR] ignoring request with ID 7090, already processing
> Oct 20 09:33:07 EGV charon[656]: 15[IKE] retransmit 3 of request with message ID 24392
> Oct 20 09:33:07 EGV charon[656]: 15[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (57 bytes)
> tunnel ping to 10.162.100.126 failed (1)
> tunnel ping to 10.162.100.126 failed (2)
> tunnel ping to 10.162.100.126 failed (3)
> Oct 20 09:33:30 EGV charon[656]: 15[IKE] retransmit 4 of request with message ID 24392
> Oct 20 09:33:30 EGV charon[656]: 15[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (57 bytes)
> Ping::PingHost, send ping to xx.xxx.xxx.xxx, ret 8
> Ping::PingHost, ping reply received
> tunnel ping to 10.162.100.126 failed (1)
> tunnel ping to 10.162.100.126 failed (2)
> Oct 20 09:34:12 EGV charon[656]: 15[IKE] retransmit 5 of request with message ID 24392
> Oct 20 09:34:12 EGV charon[656]: 15[NET] sending packet: from 10.162.225.65[4500] to xx.xxx.xxx.xxx[4500] (57 bytes)
> tunnel ping to 10.162.100.126 failed (3)
> 2022-10-20 09:34:13 restart ipsec
> ------------------------------------------------------------------------
> 
> The remote side is pinged from once per minute, if this fails two consecutive times ipsec is restarted on the local side (this is what you see at the end, we can also remove this).
> 
> How should we interpret the log. Does ipsec on the remote side simply no longer respond? Or is that to be understood differently?
> 
> What we also do not understand:
> 
> We have
> 
>    ikelifetime=86400
>    keylife=1090
>    fragmentation=yes
>    mobike=yes
>    dpddelay=2
>    dpdtimeout=10
>    dpdaction=restart
>    rekeymargin=3m
>    keyingtries=%forever
>    keyexchange=ikev2
> 
> Why is ipsec not restarted locally with the above dpd-settings?
> 
> Best regards
> René