IPsec Tunnel goes down with end of SA Lifetime - SOLVED!!!



  • Hello all!

    I have an IPsec tunnel configured between a Ubiquiti USG and pfSense. Tunnel comes up no problem and I can access anything on the pfSense's remote network ok. And from a PC on the remote network I can ping back to the USG Gateway.

    But the tunnel goes down at the end of the SA Lifetime in Phase 2. Whatever I enter as the time is how long the tunnel will stay up. While testing I've set it at 300 seconds so it times out every 5 minutes.

    When the lifetime value is reached this is what I see when I look at the widget in the dashboard.

    dashboard.jpg

    And when I look at the IPsec Status it shows connected and the time is still counting up.

    status.jpg

    To reestablish the connection I click disconnect and then click connect and it comes right back up.

    In Phase 2 I have entered the USG's ip address in 'Automatically ping host'

    Is there something else that needs to be configured for the tunnel to stay up. Or properly renegotiate the Key?

    Any help greatly appreciated.

    Thanks

    Scot



  • Still struggling to understand why this tunnel goes down...

    While testing to see if I could keep the tunnel up with traffic in either or both directions I set the lifetime to 60 seconds. And the tunnel would go down every minute. To bring it back up if I click disconnect while running a consistent ping from a pc connected to the pfSense box the tunnel comes back on its own after a couple of seconds.

    Here's the log from one of the tests this morning. I've replace the ip addresses with PFSENSE and USG to identify each.

    Hopefully someone can see something in the log that I'm not understanding as the problem.

    Again, any help greatly appreciated.

    Thanks

    ****VPN WAS JUST CONNECTED WITH A 60 SECOND LIFETIME

    Dec 30 10:25:57 charon 09[CFG] <con1000|64> selecting traffic selectors for other:
    Dec 30 10:25:57 charon 09[CFG] <con1000|64> config: 192.168.224.0/24|/0, received: 192.168.224.0/24|/0 => match: 192.168.224.0/24|/0
    Dec 30 10:25:57 charon 09[CHD] <con1000|64> CHILD_SA con1000{6597} state change: CREATED => INSTALLING
    Dec 30 10:25:57 charon 09[CHD] <con1000|64> using AES_CBC for encryption
    Dec 30 10:25:57 charon 09[CHD] <con1000|64> using HMAC_SHA1_96 for integrity
    Dec 30 10:25:57 charon 09[CHD] <con1000|64> adding inbound ESP SA
    Dec 30 10:25:57 charon 09[CHD] <con1000|64> SPI 0xca91ed7f, src USG dst PFSENSE
    Dec 30 10:25:57 charon 09[CHD] <con1000|64> adding outbound ESP SA
    Dec 30 10:25:57 charon 09[CHD] <con1000|64> SPI 0xcc3390a6, src PFSENSE dst USG
    Dec 30 10:25:57 charon 09[IKE] <con1000|64> CHILD_SA con1000{6597} established with SPIs ca91ed7f_i cc3390a6_o and TS 192.168.1.0/24|/0 === 192.168.224.0/24|/0
    Dec 30 10:25:57 charon 09[CHD] <con1000|64> CHILD_SA con1000{6597} state change: INSTALLING => INSTALLED
    Dec 30 10:25:57 charon 09[IKE] <con1000|64> activating new tasks
    Dec 30 10:25:57 charon 09[IKE] <con1000|64> nothing to initiate
    Dec 30 10:25:57 charon 09[CFG] vici client 14822 connected
    Dec 30 10:25:57 charon 10[CFG] vici client 14822 registered for: list-sa
    Dec 30 10:25:57 charon 11[CFG] vici client 14822 requests: list-sas
    Dec 30 10:25:57 charon 09[CFG] vici client 14822 disconnected
    Dec 30 10:26:03 charon 11[CFG] vici client 14823 connected
    Dec 30 10:26:03 charon 11[CFG] vici client 14823 registered for: list-sa
    Dec 30 10:26:03 charon 06[CFG] vici client 14823 requests: list-sas
    Dec 30 10:26:03 charon 11[CFG] vici client 14823 disconnected
    Dec 30 10:26:08 charon 11[CFG] vici client 14824 connected
    Dec 30 10:26:08 charon 14[CFG] vici client 14824 registered for: list-sa
    Dec 30 10:26:08 charon 11[CFG] vici client 14824 requests: list-sas
    Dec 30 10:26:08 charon 11[CFG] vici client 14824 disconnected
    Dec 30 10:26:13 charon 06[CFG] vici client 14825 connected
    Dec 30 10:26:13 charon 11[CFG] vici client 14825 registered for: list-sa
    Dec 30 10:26:13 charon 11[CFG] vici client 14825 requests: list-sas
    Dec 30 10:26:13 charon 06[CFG] vici client 14825 disconnected
    Dec 30 10:26:18 charon 08[CFG] vici client 14826 connected
    Dec 30 10:26:18 charon 06[CFG] vici client 14826 registered for: list-sa
    Dec 30 10:26:18 charon 06[CFG] vici client 14826 requests: list-sas
    Dec 30 10:26:18 charon 06[CFG] vici client 14826 disconnected
    Dec 30 10:26:23 charon 06[CFG] vici client 14827 connected
    Dec 30 10:26:23 charon 12[CFG] vici client 14827 registered for: list-sa
    Dec 30 10:26:23 charon 08[CFG] vici client 14827 requests: list-sas
    Dec 30 10:26:23 charon 12[CFG] vici client 14827 disconnected
    Dec 30 10:26:28 charon 12[CFG] vici client 14828 connected
    Dec 30 10:26:28 charon 12[CFG] vici client 14828 registered for: list-sa
    Dec 30 10:26:28 charon 12[CFG] vici client 14828 requests: list-sas
    Dec 30 10:26:28 charon 12[CFG] vici client 14828 disconnected
    Dec 30 10:26:33 charon 05[CFG] vici client 14829 connected
    Dec 30 10:26:33 charon 12[CFG] vici client 14829 registered for: list-sa
    Dec 30 10:26:33 charon 05[CFG] vici client 14829 requests: list-sas
    Dec 30 10:26:33 charon 12[CFG] vici client 14829 disconnected
    Dec 30 10:26:38 charon 16[CFG] vici client 14830 connected
    Dec 30 10:26:38 charon 13[CFG] vici client 14830 registered for: list-sa
    Dec 30 10:26:38 charon 12[CFG] vici client 14830 requests: list-sas
    Dec 30 10:26:38 charon 12[CFG] vici client 14830 disconnected
    Dec 30 10:26:58 charon 13[KNL] creating delete job for CHILD_SA ESP/0xca91ed7f/PFSENSE
    Dec 30 10:26:58 charon 16[IKE] <con1000|64> queueing CHILD_DELETE task
    Dec 30 10:26:58 charon 16[IKE] <con1000|64> activating new tasks
    Dec 30 10:26:58 charon 13[KNL] creating delete job for CHILD_SA ESP/0xcc3390a6/USG
    Dec 30 10:26:58 charon 16[IKE] <con1000|64> activating CHILD_DELETE task
    Dec 30 10:26:58 charon 16[IKE] <con1000|64> closing expired CHILD_SA con1000{6597} with SPIs ca91ed7f_i cc3390a6_o and TS 192.168.1.0/24|/0 === 192.168.224.0/24|/0
    Dec 30 10:26:58 charon 16[IKE] <con1000|64> sending DELETE for ESP CHILD_SA with SPI ca91ed7f
    Dec 30 10:26:58 charon 16[CHD] <con1000|64> CHILD_SA con1000{6597} state change: INSTALLED => DELETING
    Dec 30 10:26:58 charon 16[IKE] <con1000|64> scheduling CHILD_SA recreate after hard expire
    Dec 30 10:26:58 charon 16[IKE] <con1000|64> queueing CHILD_CREATE task
    Dec 30 10:26:58 charon 16[ENC] <con1000|64> generating INFORMATIONAL request2 [ D ]
    Dec 30 10:26:58 charon 16[NET] <con1000|64> sending packet: from PFSENSE[500] to USG[500] (76 bytes)
    Dec 30 10:26:58 charon 13[IKE] <con1000|64> queueing CHILD_DELETE task
    Dec 30 10:26:58 charon 13[IKE] <con1000|64> delaying task initiation, INFORMATIONAL exchange in progress
    Dec 30 10:26:58 charon 13[NET] <con1000|64> received packet: from USG[500] to PFSENSE[500] (76 bytes)
    Dec 30 10:26:58 charon 13[ENC] <con1000|64> parsed INFORMATIONAL response 2[ D ]
    Dec 30 10:26:58 charon 13[IKE] <con1000|64> received DELETE for ESP CHILD_SA with SPI cc3390a6
    Dec 30 10:26:58 charon 13[IKE] <con1000|64> CHILD_SA closed
    Dec 30 10:26:58 charon 13[CHD] <con1000|64> CHILD_SA con1000{6597} state change: DELETING => DELETED
    Dec 30 10:26:58 charon 13[CHD] <con1000|64> CHILD_SA con1000{6597} state change: DELETED => DESTROYING
    Dec 30 10:26:58 charon 13[KNL] <con1000|64> unable to delete SAD entry with SPI ca91ed7f: No such process (3)
    Dec 30 10:26:58 charon 13[KNL] <con1000|64> unable to delete SAD entry with SPI cc3390a6: No such process (3)
    Dec 30 10:26:58 charon 13[IKE] <con1000|64> activating new tasks
    Dec 30 10:26:58 charon 13[IKE] <con1000|64> activating CHILD_DELETE task
    Dec 30 10:26:58 charon 13[ENC] <con1000|64> generating INFORMATIONAL request3 [ ]
    Dec 30 10:26:58 charon 13[NET] <con1000|64> sending packet: from PFSENSE[500] to USG[500] (76 bytes)
    Dec 30 10:26:58 charon 13[NET] <con1000|64> received packet: from USG[500] to PFSENSE[500] (76 bytes)
    Dec 30 10:26:58 charon 13[ENC] <con1000|64> parsed INFORMATIONAL response 3[ ]
    Dec 30 10:26:58 charon 13[IKE] <con1000|64> activating new tasks
    Dec 30 10:26:58 charon 13[IKE] <con1000|64> activating CHILD_CREATE task
    Dec 30 10:26:58 charon 13[CFG] <con1000|64> proposing traffic selectors for us:
    Dec 30 10:26:58 charon 13[CFG] <con1000|64> 192.168.1.0/24|/0
    Dec 30 10:26:58 charon 13[CFG] <con1000|64> proposing traffic selectors for other:
    Dec 30 10:26:58 charon 13[CFG] <con1000|64> 192.168.224.0/24|/0
    Dec 30 10:26:58 charon 13[CFG] <con1000|64> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQDec 30 10:26:58 charon 13[IKE] <con1000|64> establishing CHILD_SA con1000{6598}
    Dec 30 10:26:58 charon 13[ENC] <con1000|64> generating CREATE_CHILD_SA request 4 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
    Dec 30 10:26:58 charon 13[NET] <con1000|64> sending packet: from PFSENSE[500] to USG[500] (572 bytes)
    Dec 30 10:26:59 charon 13[NET] <con1000|64> received packet: from USG[500] to PFSENSE[500] (76 bytes)
    Dec 30 10:26:59 charon 13[ENC] <con1000|64> parsed CREATE_CHILD_SA response4 [ N(NO_PROP) ]
    Dec 30 10:26:59 charon 13[IKE] <con1000|64> received NO_PROPOSAL_CHOSEN notify, no CHILD_SA builtDec 30 10:26:59 charon 13[CFG] <con1000|64> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ
    Dec 30 10:26:59 charon 13[IKE] <con1000|64> failed to establish CHILD_SA, keepingIKE_SA
    Dec 30 10:26:59 charon 13[CHD] <con1000|64> CHILD_SA con1000{6598} state change: CREATED => DESTROYING
    Dec 30 10:26:59 charon 13[IKE] <con1000|64> activating new tasks
    Dec 30 10:26:59 charon 13[IKE] <con1000|64> nothing to initiate

    *****AT THIS POINT THE VPN HAS GONE DOWN AND STOPPED TRANSMITTING TRAFFIC

    *****CONSISTENTLY GOES DOWN AT END OF LIFE OF THE KEY - DOESN'T MATTER THE INTERVAL - 60, 300, 1800, 3600

    Dec 30 10:27:02 charon 16[KNL] creating acquire job for policy PFSENSE/32|/0 === USG/32|/0 with reqid {12}
    Dec 30 10:27:02 charon 16[IKE] <con1000|64> queueing CHILD_CREATE task
    Dec 30 10:27:02 charon 16[IKE] <con1000|64> activating new tasks
    Dec 30 10:27:02 charon 16[IKE] <con1000|64> activating CHILD_CREATE task
    Dec 30 10:27:02 charon 16[CFG] <con1000|64> proposing traffic selectors for us:
    Dec 30 10:27:02 charon 16[CFG] <con1000|64> 192.168.1.0/24|/0
    Dec 30 10:27:02 charon 16[CFG] <con1000|64> proposing traffic selectors for other:
    Dec 30 10:27:02 charon 16[CFG] <con1000|64> 192.168.224.0/24|/0
    Dec 30 10:27:02 charon 16[CFG] <con1000|64> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ
    Dec 30 10:27:02 charon 16[IKE] <con1000|64> establishing CHILD_SA con1000{6599} reqid 12
    Dec 30 10:27:02 charon 16[ENC] <con1000|64> generating CREATE_CHILD_SA request 5 [ N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
    Dec 30 10:27:02 charon 16[NET] <con1000|64> sending packet: from PFSENSE[500] to USG[500] (572 bytes)
    Dec 30 10:27:04 charon 16[NET] <con1000|64> received packet: from USG[500] to PFSENSE[500] (76 bytes)
    Dec 30 10:27:04 charon 16[ENC] <con1000|64> parsed CREATE_CHILD_SA response5 [ N(NO_PROP) ]
    Dec 30 10:27:04 charon 16[IKE] <con1000|64> received NO_PROPOSAL_CHOSEN notify, no CHILD_SA built
    Dec 30 10:27:04 charon 16[CFG] <con1000|64> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_192/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ
    Dec 30 10:27:04 charon 16[IKE] <con1000|64> failed to establish CHILD_SA, keepingIKE_SA
    Dec 30 10:27:04 charon 16[CHD] <con1000|64> CHILD_SA con1000{6599} state change: CREATED => DESTROYING
    Dec 30 10:27:04 charon 16[IKE] <con1000|64> activating new tasks
    Dec 30 10:27:04 charon 16[IKE] <con1000|64> nothing to initiate
    Dec 30 10:27:13 charon 15[IKE] <con1000|64> sending DPD request
    Dec 30 10:27:13 charon 15[IKE] <con1000|64> queueing IKE_DPD task
    Dec 30 10:27:13 charon 15[IKE] <con1000|64> activating new tasks



  • Hello sir,

    Try one thing - Just let the two hosts located in two VPN Lans and ping mutually.

    If the Tunnel is not then down due to there is traffic passing through the Tunnel.

    Then a question ->

    IS there any KEEP ALive setting on your Ubiquiti USG side?

    I suggest you are going to enable it.

    Or, you might try changing your IPSEC mode from Tunnel to Route mode.

    In route mode, you will be able to trigger traffic from Pfsense to remote site Firewall so then keep traffic passing through the tunnel.



  • @bluegrass-168 said in IPsec Tunnel goes down with end of SA Lifetime:

    Thanks for the reply, sorry for the delay but other year-end carry over projects became a priority...

    Try one thing - Just let the two hosts located in two VPN Lans and ping mutually.

    I've done this as well and they both stop responding at the same time with the timeout.

    IS there any KEEP ALive setting on your Ubiquiti USG side?

    I've reached out this morning to ubiquiti and am waiting an answer on this.

    Or, you might try changing your IPSEC mode from Tunnel to Route mode.

    I don't see this as an option in the IPsec configuration. I'm running the latest version of pfSense - 2.4.4-RELEASE-p3

    Thanks

    Scot



  • SOLVED!!!!

    Searching for answers I strumbled on another post that was having the same problem. And it pointed me to a problem in my setup… I had PFS enabled on the pfSense and disabled on the USG.

    Thanks to those that stopped to help, hopefully this post will help someone in the future.

    Scot


Log in to reply