Project

General

Profile

Bug #1293

Updated by Tobias Brunner over 4 years ago

Hello,

We are seeing quite strange tunnel dropping issue with strongSwan and Cisco or
Juniper devices when the IPsec tunnels are being rekeyed.

Most of the time everything is working fine but sometimes after phase 2
rekeying the rekeyed tunnel gets dropped. In the case the tunnel gets dropped,
strongSwan receives CREATE_CHILD_SA request [ N(SET_WINSIZE) ] and complains
"peer initiated rekeying, but a child is half-open". Then strongSwan replies
CREATE_CHILD_SA reponse [ N(NO_PROP) ].

Here is one example, when the tunnel gets dropped with the Cisco device.
<pre>


##
## strongSwan log
##
Feb 1 04:10:29 02[NET] waiting for data on sockets
Feb 1 04:10:29 09[NET] <signal_voice_policy|3560> received packet: from 1.1.31.9[500] to 10.104.31.13[500] (476 bytes)
Feb 1 04:10:29 09[ENC] <signal_voice_policy|3560> parsed CREATE_CHILD_SA request 6 [ N(REKEY_SA) SA No KE TSi TSr ]
Feb 1 04:10:29 09[CFG] <signal_voice_policy|3560> selecting proposal:
Feb 1 04:10:29 09[CFG] <signal_voice_policy|3560> proposal matches
Feb 1 04:10:29 09[CFG] <signal_voice_policy|3560> received proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ
Feb 1 04:10:29 09[CFG] <signal_voice_policy|3560> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ
Feb 1 04:10:29 09[CFG] <signal_voice_policy|3560> selected proposal: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> got SPI c12d9712
Feb 1 04:10:29 09[CFG] <signal_voice_policy|3560> selecting traffic selectors for us:
Feb 1 04:10:29 09[CFG] <signal_voice_policy|3560> config: 1.1.31.18/32, received: 1.1.31.18/32 => match: 1.1.31.18/32
Feb 1 04:10:29 09[CFG] <signal_voice_policy|3560> selecting traffic selectors for other:
Feb 1 04:10:29 09[CFG] <signal_voice_policy|3560> config: 10.102.31.0/24, received: 10.102.31.0/24 => match: 10.102.31.0/24
Feb 1 04:10:29 09[CHD] <signal_voice_policy|3560> using AES_CBC for encryption
Feb 1 04:10:29 09[CHD] <signal_voice_policy|3560> using HMAC_SHA1_96 for integrity
Feb 1 04:10:29 09[CHD] <signal_voice_policy|3560> adding inbound ESP SA
Feb 1 04:10:29 09[CHD] <signal_voice_policy|3560> SPI 0xc12d9712, src 1.1.31.9 dst 10.104.31.13
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> adding SAD entry with SPI c12d9712 and reqid {18} (mark 0/0x00000000)
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> using encryption algorithm AES_CBC with key size 256
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> using integrity algorithm HMAC_SHA1_96 with key size 160
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> using replay window of 32 packets
Feb 1 04:10:29 09[CHD] <signal_voice_policy|3560> adding outbound ESP SA
Feb 1 04:10:29 09[CHD] <signal_voice_policy|3560> SPI 0x59c54e59, src 10.104.31.13 dst 1.1.31.9
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> adding SAD entry with SPI 59c54e59 and reqid {18} (mark 0/0x00000000)
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> using encryption algorithm AES_CBC with key size 256
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> using integrity algorithm HMAC_SHA1_96 with key size 160
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> using replay window of 32 packets
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> policy 1.1.31.18/32 === 10.102.31.0/24 out (mark 0/0x00000000) already exists, increasing refcount
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> policy 10.102.31.0/24 === 1.1.31.18/32 in (mark 0/0x00000000) already exists, increasing refcount
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> policy 10.102.31.0/24 === 1.1.31.18/32 fwd (mark 0/0x00000000) already exists, increasing refcount
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> policy 1.1.31.18/32 === 10.102.31.0/24 out (mark 0/0x00000000) already exists, increasing refcount
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> updating policy 1.1.31.18/32 === 10.102.31.0/24 out (mark 0/0x00000000)
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> policy 10.102.31.0/24 === 1.1.31.18/32 in (mark 0/0x00000000) already exists, increasing refcount
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> updating policy 10.102.31.0/24 === 1.1.31.18/32 in (mark 0/0x00000000)
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> policy 10.102.31.0/24 === 1.1.31.18/32 fwd (mark 0/0x00000000) already exists, increasing refcount
Feb 1 04:10:29 09[KNL] <signal_voice_policy|3560> updating policy 10.102.31.0/24 === 1.1.31.18/32 fwd (mark 0/0x00000000)
Feb 1 04:10:29 09[IKE] <signal_voice_policy|3560> CHILD_SA signal_voice_policy{4386} established with SPIs c12d9712_i 59c54e59_o and TS 1.1.31.18/32 === 10.102.31.0/24
Feb 1 04:10:29 09[ENC] <signal_voice_policy|3560> generating CREATE_CHILD_SA response 6 [ SA No KE TSi TSr ]
Feb 1 04:10:29 09[NET] <signal_voice_policy|3560> sending packet: from 10.104.31.13[500] to 1.1.31.9[500] (476 bytes)
Feb 1 04:10:29 04[NET] sending packet: from 10.104.31.13[500] to 1.1.31.9[500]
Feb 1 04:10:29 02[NET] received packet: from 1.1.31.9[500] to 10.104.31.13[500]
Feb 1 04:10:29 02[NET] waiting for data on sockets
Feb 1 04:10:29 08[NET] <signal_voice_policy|3560> received packet: from 1.1.31.9[500] to 10.104.31.13[500] (76 bytes)
Feb 1 04:10:29 08[ENC] <signal_voice_policy|3560> parsed INFORMATIONAL request 7 [ N(INVAL_SPI) ]
Feb 1 04:10:29 08[ENC] <signal_voice_policy|3560> generating INFORMATIONAL response 7 [ ]
Feb 1 04:10:29 08[NET] <signal_voice_policy|3560> sending packet: from 10.104.31.13[500] to 1.1.31.9[500] (76 bytes)
Feb 1 04:10:30 04[NET] sending packet: from 10.104.31.13[500] to 1.1.31.9[500]
Feb 1 04:10:30 02[NET] received packet: from 1.1.31.9[500] to 10.104.31.13[500]
Feb 1 04:10:30 02[NET] waiting for data on sockets
</pre>


<pre>
##
## Here strongSwan receives the request to set the window size but
## we get the error... and strongSwan replies with "NO_PROP"
##

Feb 1 04:10:30 06[NET] <signal_voice_policy|3560> received packet: from 1.1.31.9[500] to 10.104.31.13[500] (428 bytes)
Feb 1 04:10:30 06[ENC] <signal_voice_policy|3560> parsed CREATE_CHILD_SA request 8 [ SA No KE N(SET_WINSIZE) ]
Feb 1 04:10:30 06[IKE] <signal_voice_policy|3560> peer initiated rekeying, but a child is half-open
Feb 1 04:10:30 06[ENC] <signal_voice_policy|3560> generating CREATE_CHILD_SA response 8 [ N(NO_PROP) ]
Feb 1 04:10:30 06[NET] <signal_voice_policy|3560> sending packet: from 10.104.31.13[500] to 1.1.31.9[500] (76 bytes)
Feb 1 04:10:30 04[NET] sending packet: from 10.104.31.13[500] to 1.1.31.9[500]
Feb 1 04:10:30 02[NET] received packet: from 1.1.31.9[500] to 10.104.31.13[500]
Feb 1 04:10:30 02[NET] waiting for data on sockets
</pre>


<pre>
##
## Cisco is not happy with the reply and it decides to delete the tunnel.
##

Feb 1 04:10:30 11[NET] <signal_voice_policy|3560> received packet: from 1.1.31.9[500] to 10.104.31.13[500] (76 bytes)
Feb 1 04:10:30 11[ENC] <signal_voice_policy|3560> parsed INFORMATIONAL request 9 [ D ]
Feb 1 04:10:30 11[IKE] <signal_voice_policy|3560> received DELETE for ESP CHILD_SA with SPI 85d78273
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> querying SAD entry with SPI cbd2e0fe (mark 0/0x00000000)
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> querying SAD entry with SPI 85d78273 (mark 0/0x00000000)
Feb 1 04:10:30 11[IKE] <signal_voice_policy|3560> closing CHILD_SA signal_voice_policy{4383} with SPIs cbd2e0fe_i (163940 bytes) 85d78273_o (159124 bytes) and TS 1.1.31.18/32 === 10.102.31.0/24
Feb 1 04:10:30 11[IKE] <signal_voice_policy|3560> sending DELETE for ESP CHILD_SA with SPI cbd2e0fe
Feb 1 04:10:30 11[IKE] <signal_voice_policy|3560> CHILD_SA closed
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> deleting policy 1.1.31.18/32 === 10.102.31.0/24 out (mark 0/0x00000000)
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> policy still used by another CHILD_SA, not removed
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> deleting policy 10.102.31.0/24 === 1.1.31.18/32 in (mark 0/0x00000000)
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> policy still used by another CHILD_SA, not removed
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> deleting policy 10.102.31.0/24 === 1.1.31.18/32 fwd (mark 0/0x00000000)
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> policy still used by another CHILD_SA, not removed
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> deleting policy 1.1.31.18/32 === 10.102.31.0/24 out (mark 0/0x00000000)
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> policy still used by another CHILD_SA, not removed
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> deleting policy 10.102.31.0/24 === 1.1.31.18/32 in (mark 0/0x00000000)
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> policy still used by another CHILD_SA, not removed
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> deleting policy 10.102.31.0/24 === 1.1.31.18/32 fwd (mark 0/0x00000000)
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> policy still used by another CHILD_SA, not removed
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> deleting SAD entry with SPI cbd2e0fe (mark 0/0x00000000)
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> deleted SAD entry with SPI cbd2e0fe (mark 0/0x00000000)
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> deleting SAD entry with SPI 85d78273 (mark 0/0x00000000)
Feb 1 04:10:30 11[KNL] <signal_voice_policy|3560> deleted SAD entry with SPI 85d78273 (mark 0/0x00000000)
Feb 1 04:10:30 11[ENC] <signal_voice_policy|3560> generating INFORMATIONAL response 9 [ D ]
Feb 1 04:10:30 11[NET] <signal_voice_policy|3560> sending packet: from 10.104.31.13[500] to 1.1.31.9[500] (76 bytes)
Feb 1 04:10:30 04[NET] sending packet: from 10.104.31.13[500] to 1.1.31.9[500]
Feb 1 04:10:51 02[NET] received packet: from 1.1.31.9[500] to 10.106.31.13[500]
Feb 1 04:10:51 02[NET] waiting for data on sockets
Feb 1 04:10:51 10[NET] <emnet_policy|3561> received packet: from 1.1.31.9[500] to 10.106.31.13[500] (76 bytes)
Feb 1 04:10:51 10[ENC] <emnet_policy|3561> parsed INFORMATIONAL request 2 [ ]
Feb 1 04:10:51 10[ENC] <emnet_policy|3561> generating INFORMATIONAL response 2 [ ]
Feb 1 04:10:51 10[NET] <emnet_policy|3561> sending packet: from 10.106.31.13[500] to 1.1.31.9[500] (76 bytes)
Feb 1 04:10:51 04[NET] sending packet: from 10.106.31.13[500] to 1.1.31.9[500]
Feb 1 04:11:25 02[NET] received packet: from 1.1.31.9[500] to 10.104.31.13[500]
Feb 1 04:11:25 02[NET] waiting for data on sockets
Feb 1 04:11:25 05[NET] <signal_voice_policy|3560> received packet: from 1.1.31.9[500] to 10.104.31.13[500] (76 bytes)
Feb 1 04:11:25 05[ENC] <signal_voice_policy|3560> parsed INFORMATIONAL request 10 [ D ]
Feb 1 04:11:25 05[IKE] <signal_voice_policy|3560> received DELETE for IKE_SA signal_voice_policy[3560]
Feb 1 04:11:25 05[IKE] <signal_voice_policy|3560> deleting IKE_SA signal_voice_policy[3560] between 10.104.31.13[10.104.31.13]...1.1.31.9[1.1.31.9]
Feb 1 04:11:25 05[IKE] <signal_voice_policy|3560> IKE_SA signal_voice_policy[3560] state change: ESTABLISHED => DELETING
Feb 1 04:11:25 05[IKE] <signal_voice_policy|3560> restarting CHILD_SA signal_voice_policy

##
## Since we have enabled
## closeaction=restart
## in the ipsec.conf file, strongSwan recovers the tunnels but nevertheless
## there is an unfortunate break in the traffic.
##
</pre>
<pre>


##
## From the Cisco point of view, the situation looks like below (the clocks
## were not synced, this is the same situation as shown above).
##

*Feb 1 01:50:54.250: IKEv2:(SA ID = 2):Sending Packet [To 10.104.31.13:500/From 1.1.31.9:500/VRF i0:f0]
Initiator SPI : BEA75F41D21B0BEB - Responder SPI : 30453E7655BCD79D Message id: 8
IKEv2 CREATE_CHILD_SA Exchange REQUEST
Payload contents:
ENCR

*Feb 1 01:50:54.306: IKEv2:(SA ID = 2):Received Packet [From 10.104.31.13:500/To 1.1.31.9:500/VRF i0:f0]
Initiator SPI : BEA75F41D21B0BEB - Responder SPI : 30453E7655BCD79D Message id: 8
IKEv2 CREATE_CHILD_SA Exchange RESPONSE
Payload contents:
NOTIFY(NO_PROPOSAL_CHOSEN)

*Feb 1 01:50:54.306: IKEv2:(SA ID = 2):Processing any notify-messages in child SA exchange
*Feb 1 01:50:54.306: IKEv2:(SA ID = 2):Create child exchange failed

*Feb 1 01:50:54.306: IKEv2:(SA ID = 2):
*Feb 1 01:50:54.306: IKEv2:(SA ID = 2):IKE SA rekey failed
*Feb 1 01:50:54.306: IKEv2:(SA ID = 2):Abort exchange
*Feb 1 01:50:54.306: IKEv2:(SA ID = 3):Deleting SA

*Feb 1 01:50:54.306: IKEv2:(SA ID = 2):Sending Packet [To 10.104.31.13:500/From 1.1.31.9:500/VRF i0:f0]
Initiator SPI : BEA75F41D21B0BEB - Responder SPI : 30453E7655BCD79D Message id: 9
IKEv2 INFORMATIONAL Exchange REQUEST
Payload contents:
ENCR
</pre>


#######################

We have seen the issue with strongSwan versions 5.3.0 and 5.3.5, and as
already mentioed it happens with Cisco and Juniper devices. Since the same
issue happens with devices from two different vendors we suspecting there could be
something wrong on the strongSwan side. What do you think?

The ipsec.conf is as below. The lifetime values are intentionally so short
that we can repeat the problem easily.

We can provide logs from longer period of time, or generate more
detailed logs, if that helps to solve the issue. Just let us know what
logging levels would be useful.

<pre>


## strongSwan.conf ##

config setup
uniqueids=never

conn %default
authby=secret
rekey=no
rekeymargin=30s
rekeyfuzz=0%
mobike=no
keyingtries=%forever
keyexchange=ikev2
ike=aes256-sha1-modp2048!
esp=aes256-sha1-modp2048!
ikelifetime=240
lifebytes=67107840
lifetime=180

conn signal_voice_policy
type=tunnel
left=10.104.31.13
leftsubnet=1.1.31.18/32
right=1.1.31.9
rightsubnet=10.102.31.0/24
closeaction=restart
auto=start

conn emnet_policy
type=tunnel
left=10.106.31.13
leftsubnet=1.1.31.22/32
right=1.1.31.9
rightsubnet=0.0.0.0/0
closeaction=restart
auto=start

conn ssh_policy
type=passthrough
left=10.106.31.13
leftsubnet=10.106.31.13/32
rightsubnet=0.0.0.0/0
rightprotoport=tcp/ssh
authby=never
auto=route

conn ssh_policy2
type=passthrough
left=10.106.31.13
leftsubnet=10.106.31.13/32
leftprotoport=tcp/ssh
rightsubnet=0.0.0.0/0
authby=never
auto=route
</pre>


Br, Lasse

Back