Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    Phase 2 rekey takes 180 seconds

    Scheduled Pinned Locked Moved IPsec
    11 Posts 3 Posters 1.1k Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • K
      Konstanti @scourtney2000
      last edited by

      @scourtney2000

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

      1 Reply Last reply Reply Quote 0
      • S
        scourtney2000
        last edited by

        @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

        1 Reply Last reply Reply Quote 0
        • DerelictD
          Derelict LAYER 8 Netgate
          last edited by 

          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.

          Chattanooga, Tennessee, USA
          A comprehensive network diagram is worth 10,000 words and 15 conference calls.
          DO NOT set a source address/port in a port forward or firewall rule unless you KNOW you need it!
          Do Not Chat For Help! NO_WAN_EGRESS(TM)

          S 1 Reply Last reply Reply Quote 0
          • S
            scourtney2000 @Derelict
            last edited by

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

            1 Reply Last reply Reply Quote 0
            • S
              scourtney2000
              last edited by

              0_1549933343714_ipsec_status.jpg

              1 Reply Last reply Reply Quote 0
              • DerelictD
                Derelict LAYER 8 Netgate
                last edited by Derelict

                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?

                Chattanooga, Tennessee, USA
                A comprehensive network diagram is worth 10,000 words and 15 conference calls.
                DO NOT set a source address/port in a port forward or firewall rule unless you KNOW you need it!
                Do Not Chat For Help! NO_WAN_EGRESS(TM)

                1 Reply Last reply Reply Quote 0
                • S
                  scourtney2000
                  last edited by

                  The other side say no bytes in also.

                  1 Reply Last reply Reply Quote 0
                  • S
                    scourtney2000
                    last edited by

                    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.

                    1 Reply Last reply Reply Quote 0
                    • S
                      scourtney2000
                      last edited by

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

                      1 Reply Last reply Reply Quote 0
                      • DerelictD
                        Derelict LAYER 8 Netgate
                        last edited by

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

                        Chattanooga, Tennessee, USA
                        A comprehensive network diagram is worth 10,000 words and 15 conference calls.
                        DO NOT set a source address/port in a port forward or firewall rule unless you KNOW you need it!
                        Do Not Chat For Help! NO_WAN_EGRESS(TM)

                        1 Reply Last reply Reply Quote 0
                        • First post
                          Last post
                        Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.