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



  • @scourtney2000

    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


  • 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.



  • @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_1549933343714_ipsec_status.jpg


  • 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?



  • 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?


  • LAYER 8 Netgate

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