Phase 2 rekey takes 180 seconds
-
I have pfSense 2.4.4 p2 on two sides of an IPSEC ikev2 tunnel that is using PSK. During phase 2 rekey it takes around 3 mintues for the tunnel to come back up. During that time, the new phase 2 sits there and shows bytes out but no bytes in. I have tried both Tunnel and VTI and both have the same trouble. I am running CARP on one side of the tunnel.
I tinkered with the settings over and over trying new things. I settled for increasing my Phase 1 and Phase 2 lifetimes to minimize outages. I want to learn more about how to troubleshoot this issue. What other things should I be looking at?
I have gone as far as to destroy the tunnel setting on both side and restarting several times.
Thanks
-
Hey
show the logs where you can see what happens during the process of Rekeying -
@konstanti said in Phase 2 rekey takes 180 seconds:
you can see what happens during the process of Rekeying
[0_1549927906507_ipsec.log](Uploading 100%) 0_1549927946792_ipsec_log.txt
-
Feb 11 18:15:15 charon 09[KNL] creating rekey job for CHILD_SA ESP/0xc67af502/x.x.x.x Feb 11 18:15:15 charon 09[IKE] <con1000|1> queueing CHILD_REKEY task Feb 11 18:15:15 charon 09[IKE] <con1000|1> activating new tasks Feb 11 18:15:15 charon 09[IKE] <con1000|1> activating CHILD_REKEY task Feb 11 18:15:15 charon 09[CFG] <con1000|1> proposing traffic selectors for us: Feb 11 18:15:15 charon 09[CFG] <con1000|1> 10.255.255.8/30|/0 Feb 11 18:15:15 charon 09[CFG] <con1000|1> 0.0.0.0/0|/0 Feb 11 18:15:15 charon 09[CFG] <con1000|1> proposing traffic selectors for other: Feb 11 18:15:15 charon 09[CFG] <con1000|1> 10.255.255.9/32|/0 Feb 11 18:15:15 charon 09[CFG] <con1000|1> 0.0.0.0/0|/0 Feb 11 18:15:15 charon 09[CFG] <con1000|1> configured proposals: ESP:AES_CBC_128/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ Feb 11 18:15:15 charon 09[IKE] <con1000|1> establishing CHILD_SA con1000{4} reqid 1000 Feb 11 18:15:15 charon 09[CHD] <con1000|1> CHILD_SA con1000{1} state change: INSTALLED => REKEYING Feb 11 18:15:15 charon 09[ENC] <con1000|1> generating CREATE_CHILD_SA request 2162 [ N(REKEY_SA) N(ESP_TFC_PAD_N) SA No KE TSi TSr ] Feb 11 18:15:15 charon 09[NET] <con1000|1> sending packet: from y.y.y.y[500] to x.x.x.x[500] (364 bytes) Feb 11 18:15:15 charon 09[NET] <con1000|1> received packet: from x.x.x.x[500] to y.y.y.y[500] (348 bytes) Feb 11 18:15:15 charon 09[ENC] <con1000|1> parsed CREATE_CHILD_SA response 2162 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ] Feb 11 18:15:15 charon 09[IKE] <con1000|1> received ESP_TFC_PADDING_NOT_SUPPORTED notify Feb 11 18:15:15 charon 09[IKE] <con1000|1> received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding Feb 11 18:15:15 charon 09[CFG] <con1000|1> selecting proposal: Feb 11 18:15:15 charon 09[CFG] <con1000|1> proposal matches Feb 11 18:15:15 charon 09[CFG] <con1000|1> received proposals: ESP:AES_CBC_128/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ Feb 11 18:15:15 charon 09[CFG] <con1000|1> configured proposals: ESP:AES_CBC_128/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ Feb 11 18:15:15 charon 09[CFG] <con1000|1> selected proposal: ESP:AES_CBC_128/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ Feb 11 18:15:15 charon 09[CFG] <con1000|1> selecting traffic selectors for us: Feb 11 18:15:15 charon 09[CFG] <con1000|1> config: 10.255.255.8/30|/0, received: 0.0.0.0/0|/0 => match: 10.255.255.8/30|/0 Feb 11 18:15:15 charon 09[CFG] <con1000|1> config: 0.0.0.0/0|/0, received: 0.0.0.0/0|/0 => match: 0.0.0.0/0|/0 Feb 11 18:15:15 charon 09[CFG] <con1000|1> selecting traffic selectors for other: Feb 11 18:15:15 charon 09[CFG] <con1000|1> config: 10.255.255.9/32|/0, received: 0.0.0.0/0|/0 => match: 10.255.255.9/32|/0 Feb 11 18:15:15 charon 09[CFG] <con1000|1> config: 0.0.0.0/0|/0, received: 0.0.0.0/0|/0 => match: 0.0.0.0/0|/0 Feb 11 18:15:15 charon 09[CHD] <con1000|1> CHILD_SA con1000{4} state change: CREATED => INSTALLING Feb 11 18:15:15 charon 09[CHD] <con1000|1> using AES_CBC for encryption Feb 11 18:15:15 charon 09[CHD] <con1000|1> using HMAC_SHA1_96 for integrity Feb 11 18:15:15 charon 09[CHD] <con1000|1> adding inbound ESP SA Feb 11 18:15:15 charon 09[CHD] <con1000|1> SPI 0xccd147c5, src x.x.x.x dst y.y.y.y Feb 11 18:15:15 charon 09[CHD] <con1000|1> registering outbound ESP SA Feb 11 18:15:15 charon 09[CHD] <con1000|1> SPI 0xc4672f68, src y.y.y.y dst x.x.x.x Feb 11 18:15:15 charon 09[IKE] <con1000|1> inbound CHILD_SA con1000{4} established with SPIs ccd147c5_i c4672f68_o and TS 0.0.0.0/0|/0 === 0.0.0.0/0|/0 Feb 11 18:15:15 charon 09[CHD] <con1000|1> CHILD_SA con1000{4} state change: INSTALLING => INSTALLED Feb 11 18:15:15 charon 09[CHD] <con1000|1> adding outbound ESP SA Feb 11 18:15:15 charon 09[CHD] <con1000|1> SPI 0xc4672f68, src y.y.y.y dst x.x.x.x Feb 11 18:15:15 charon 09[IKE] <con1000|1> outbound CHILD_SA con1000{4} established with SPIs ccd147c5_i c4672f68_o and TS 0.0.0.0/0|/0 === 0.0.0.0/0|/0 Feb 11 18:15:15 charon 09[CHD] <con1000|1> CHILD_SA con1000{1} state change: REKEYING => REKEYED Feb 11 18:15:15 charon 09[IKE] <con1000|1> reinitiating already active tasks Feb 11 18:15:15 charon 09[IKE] <con1000|1> CHILD_REKEY task Feb 11 18:15:15 charon 09[IKE] <con1000|1> closing CHILD_SA con1000{1} with SPIs cac7ac71_i (0 bytes) c67af502_o (1920 bytes) and TS 0.0.0.0/0|/0 === 0.0.0.0/0|/0 Feb 11 18:15:15 charon 09[IKE] <con1000|1> sending DELETE for ESP CHILD_SA with SPI cac7ac71 Feb 11 18:15:15 charon 09[CHD] <con1000|1> CHILD_SA con1000{1} state change: REKEYED => DELETING Feb 11 18:15:15 charon 09[ENC] <con1000|1> generating INFORMATIONAL request 2163 [ D ] Feb 11 18:15:15 charon 09[NET] <con1000|1> sending packet: from y.y.y.y[500] to x.x.x.x[500] (76 bytes) Feb 11 18:15:15 charon 09[NET] <con1000|1> received packet: from x.x.x.x[500] to y.y.y.y[500] (76 bytes) Feb 11 18:15:15 charon 09[ENC] <con1000|1> parsed INFORMATIONAL response 2163 [ D ] Feb 11 18:15:15 charon 09[IKE] <con1000|1> received DELETE for ESP CHILD_SA with SPI c67af502 Feb 11 18:15:15 charon 09[IKE] <con1000|1> CHILD_SA closed Feb 11 18:15:15 charon 09[CHD] <con1000|1> CHILD_SA con1000{1} state change: DELETING => DELETED
Looks like this side is doing everything it is supposed to all at second :15.
What are you seeing that gives you the impression that it is taking 3 minutes?
Perhaps it has something to do with the way you configured the HA cluster.
That log right there looks absolutely fine.
-
It does pass traffic for 3 minutes. I have a continuous ping running at the time of the rekey. It takes approximately 3 minutes before the traffic passes. On both sides of the tunnel the VPN Status indicates Bytes in as 0.
-
-
If bytes in is 0 we need to see the other side.
Packet capture ICMP on the IPsec interface. Do you see the echo requests going out and no reply?
-
The other side say no bytes in also.
-
The pattern I see everytime is Phase 1 connects. A single Phase 2 comes up. I can ping for a minute through the tunnel. Another Phase 2 comes up. I can not ping. Bytes-in on both sides displays 0. Then 3 minutes later I can ping through the tunnel. Only the second Phase 2 is actually active. The first Phase 1 is never destroyed.
-
If I am using VTI for phase 2 along with CARP would I need to create a VIP for for the tunnel?
-
No. The tunnel interface addresses are specified in the Phase 2 configuration.