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é
