4. Phase 2 rekey takes 180 seconds

Phase 2 rekey takes 180 seconds

  • S

    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

    0
    K
     1 Reply
  • K

    @scourtney2000

    Hey
    show the logs where you can see what happens during the process of Rekeying

    0
  • S

    @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

    0
  • LAYER 8 Netgate 

    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.

    0
    S
     1 Reply
  • S

    @derelict

    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.

    0
  • S

    0_1549933343714_ipsec_status.jpg

    0
  • LAYER 8 Netgate

    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?

    0
  • S

    The other side say no bytes in also.

    0
  • S

    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.

    0
  • S

    If I am using VTI for phase 2 along with CARP would I need to create a VIP for for the tunnel?

    0
  • LAYER 8 Netgate

    No. The tunnel interface addresses are specified in the Phase 2 configuration.

    0
 

Products

Applications

Support

Services

News

Resources

Company

Our Mission

As host of the pfSense open source firewall project, Netgate believes in enhancing network connectivity that maintains both security and privacy. We also believe everyone should be able to afford it.

Subscribe to our Newsletter

Product information, software announcements, and special offers. See our newsletter archive for past announcements.

© Copyright 2002 - 2019 Rubicon Communications, LLC | Privacy Policy