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

    Phase 2 is not establishing

    Scheduled Pinned Locked Moved IPsec
    7 Posts 2 Posters 1.0k 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.
    • S
      shshs
      last edited by shshs

      Greetings,

      Dear experts, I'll be appreciated for your help in the following issue. I have pfSense cluster built on KVM virtualisation platform:

      2.4.4-RELEASE-p3 (amd64) 
built on Wed May 15 18:53:44 EDT 2019 
FreeBSD 11.2-RELEASE-p10

      Recently I setup site to site VPN with remote Cisco ASR platform. While IKEv1 phase1 is established I can not make phase2 even be triggered by SA traffic:
      7de81d18-9cd8-453d-ba18-29a208c2994f-image.png
      While sniffing traffic towards remote tunnel destination in tcpdump I see only IKE traffic, but not ESP (tcpdump -ni <ifname> host <remote_tunnel_endpoint>):
      1b099242-f09c-43db-88e1-ba5a60287695-image.png
      While triggering phase2 establishment by pinging the destination behind the remote end of this tunnel I see traffic in tcpdump coming from LAN interface, but see nothing in tcpdump of enc0 interface, so the packets are just silently dropped. In a firewall configuration regarding the IPSec interface I have allow any any rule.

      Please advice what could be investigated in addition. Thank you.

      1 Reply Last reply Reply Quote 0
      • jimpJ
        jimp Rebel Alliance Developer Netgate
        last edited by

        You have blocked out any information which might have helped suggest a cause.

        If traffic does not enter IPsec, then there are two main possibilities:

        • The traffic is not interesting to IPsec (does not match Phase 2 source/destination networks)
        • The traffic is hitting a policy routing rule which is forcing it around the tunnel (e.g. rule on LAN with a gateway set)

        If it's VTI then it gets more complicated but would most likely be a routing issue.

        If the P2 still fails to establish there must be some clue in the IPsec logs on one or both sides. Increase the logging verboseness and try again. Stop and start IPsec and try initiating from the other side, too.

        Remember: Upvote with the 👍 button for any user/post you find to be helpful, informative, or deserving of recognition!

        Need help fast? Netgate Global Support!

        Do not Chat/PM for help!

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

          @jimp

          Thanks for help, man. I've checked twice that the interesting traffic is falling under phase2 subnets, they are configured on both ends symmetrically. And there are no policy rules on pfSense at all. But I've increased IPsec Logging Controls: IPsec traffic and StrongSwan Lib, - to a "Highest" level, then restart the service and IPSec as well. There logs are below:

          Nov 19 17:36:18	charon		14[CFG] vici client 2505 connected
Nov 19 17:36:18	charon		09[CFG] vici client 2505 registered for: list-sa
Nov 19 17:36:18	charon		14[CFG] vici client 2505 requests: list-sas
Nov 19 17:36:18	charon		14[CFG] vici client 2505 disconnected
Nov 19 17:36:18	charon		14[CFG] received stroke: terminate 'con3000[130]'
Nov 19 17:36:18	charon		09[CHD] <con3000|130> CHILD_SA con3000{142} state change: CREATED => DESTROYING
Nov 19 17:36:18	charon		09[KNL] <con3000|130> unable to delete SAD entry with SPI cdd71510: No such process (3)
Nov 19 17:36:18	charon		09[IKE] <con3000|130> queueing ISAKMP_DELETE task
Nov 19 17:36:18	charon		09[IKE] <con3000|130> activating new tasks
Nov 19 17:36:18	charon		09[IKE] <con3000|130> activating ISAKMP_DELETE task
Nov 19 17:36:18	charon		09[IKE] <con3000|130> deleting IKE_SA con3000[130] between <MY_SOURCE_IP>[<MY_SOURCE_IP>]...<REMOTE_IP>[<REMOTE_IP>]
Nov 19 17:36:18	charon		09[IKE] <con3000|130> sending DELETE for IKE_SA con3000[130]
Nov 19 17:36:18	charon		09[IKE] <con3000|130> IKE_SA con3000[130] state change: ESTABLISHED => DELETING
Nov 19 17:36:18	charon		09[ENC] <con3000|130> generating INFORMATIONAL_V1 request 148469401 [ HASH D ]
Nov 19 17:36:18	charon		09[NET] <con3000|130> sending packet: from <MY_SOURCE_IP>[500] to <REMOTE_IP>[500] (140 bytes)
Nov 19 17:36:18	charon		09[IKE] <con3000|130> IKE_SA con3000[130] state change: DELETING => DESTROYING
Nov 19 17:36:19	charon		11[CFG] vici client 2506 connected
Nov 19 17:36:19	charon		11[CFG] vici client 2506 registered for: list-sa
Nov 19 17:36:19	charon		09[CFG] vici client 2506 requests: list-sas
Nov 19 17:36:19	charon		09[CFG] vici client 2506 disconnected
Nov 19 17:36:23	charon		08[CFG] vici client 2507 connected
Nov 19 17:36:23	charon		08[CFG] vici client 2507 registered for: list-sa
Nov 19 17:36:23	charon		13[CFG] vici client 2507 requests: list-sas
Nov 19 17:36:23	charon		13[CFG] vici client 2507 disconnected
Nov 19 17:36:24	charon		13[CFG] vici client 2508 connected
Nov 19 17:36:24	charon		13[CFG] vici client 2508 registered for: list-sa
Nov 19 17:36:24	charon		08[CFG] vici client 2508 requests: list-sas
Nov 19 17:36:24	charon		11[CFG] vici client 2508 disconnected
Nov 19 17:36:25	charon		11[KNL] creating acquire job for policy <MY_SOURCE_IP>/32|/0 === <REMOTE_IP>/32|/0 with reqid {10}
Nov 19 17:36:25	charon		11[IKE] <con3000|131> queueing ISAKMP_VENDOR task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> queueing ISAKMP_CERT_PRE task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> queueing MAIN_MODE task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> queueing ISAKMP_CERT_POST task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> queueing ISAKMP_NATD task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> queueing QUICK_MODE task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> activating new tasks
Nov 19 17:36:25	charon		11[IKE] <con3000|131> activating ISAKMP_VENDOR task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> activating ISAKMP_CERT_PRE task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> activating MAIN_MODE task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> activating ISAKMP_CERT_POST task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> activating ISAKMP_NATD task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> sending XAuth vendor ID
Nov 19 17:36:25	charon		11[IKE] <con3000|131> sending DPD vendor ID
Nov 19 17:36:25	charon		11[IKE] <con3000|131> sending FRAGMENTATION vendor ID
Nov 19 17:36:25	charon		11[IKE] <con3000|131> sending NAT-T (RFC 3947) vendor ID
Nov 19 17:36:25	charon		11[IKE] <con3000|131> sending draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Nov 19 17:36:25	charon		11[IKE] <con3000|131> initiating Main Mode IKE_SA con3000[131] to <REMOTE_IP>
Nov 19 17:36:25	charon		11[IKE] <con3000|131> IKE_SA con3000[131] state change: CREATED => CONNECTING
Nov 19 17:36:25	charon		11[CFG] <con3000|131> configured proposals: IKE:AES_CBC_256/HMAC_SHA2_512_256/PRF_HMAC_SHA2_512/MODP_2048
Nov 19 17:36:25	charon		11[ENC] <con3000|131> generating ID_PROT request 0 [ SA V V V V V ]
Nov 19 17:36:25	charon		11[NET] <con3000|131> sending packet: from <MY_SOURCE_IP>[500] to <REMOTE_IP>[500] (180 bytes)
Nov 19 17:36:25	charon		11[NET] <con3000|131> received packet: from <REMOTE_IP>[500] to <MY_SOURCE_IP>[500] (104 bytes)
Nov 19 17:36:25	charon		11[ENC] <con3000|131> parsed ID_PROT response 0 [ SA V ]
Nov 19 17:36:25	charon		11[IKE] <con3000|131> received NAT-T (RFC 3947) vendor ID
Nov 19 17:36:25	charon		11[CFG] <con3000|131> selecting proposal:
Nov 19 17:36:25	charon		11[CFG] <con3000|131> proposal matches
Nov 19 17:36:25	charon		11[CFG] <con3000|131> received proposals: IKE:AES_CBC_256/HMAC_SHA2_512_256/PRF_HMAC_SHA2_512/MODP_2048
Nov 19 17:36:25	charon		11[CFG] <con3000|131> configured proposals: IKE:AES_CBC_256/HMAC_SHA2_512_256/PRF_HMAC_SHA2_512/MODP_2048
Nov 19 17:36:25	charon		11[CFG] <con3000|131> selected proposal: IKE:AES_CBC_256/HMAC_SHA2_512_256/PRF_HMAC_SHA2_512/MODP_2048
Nov 19 17:36:25	charon		11[IKE] <con3000|131> reinitiating already active tasks
Nov 19 17:36:25	charon		11[IKE] <con3000|131> ISAKMP_VENDOR task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> MAIN_MODE task
Nov 19 17:36:25	charon		11[LIB] size of DH secret exponent: 2047 bits
Nov 19 17:36:25	charon		11[LIB] <con3000|131> size of DH secret exponent: 2047 bits
Nov 19 17:36:25	charon		11[ENC] <con3000|131> generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Nov 19 17:36:25	charon		11[NET] <con3000|131> sending packet: from <MY_SOURCE_IP>[500] to <REMOTE_IP>[500] (460 bytes)
Nov 19 17:36:25	charon		11[NET] <con3000|131> received packet: from <REMOTE_IP>[500] to <MY_SOURCE_IP>[500] (520 bytes)
Nov 19 17:36:25	charon		11[ENC] <con3000|131> parsed ID_PROT response 0 [ KE No V V V V NAT-D NAT-D ]
Nov 19 17:36:25	charon		11[IKE] <con3000|131> received Cisco Unity vendor ID
Nov 19 17:36:25	charon		11[IKE] <con3000|131> received DPD vendor ID
Nov 19 17:36:25	charon		11[ENC] <con3000|131> received unknown vendor ID: 38:00:7c:6d:78:e2:b4:01:64:fd:89:49:bf:15:44:a7
Nov 19 17:36:25	charon		11[IKE] <con3000|131> received XAuth vendor ID
Nov 19 17:36:25	charon		11[IKE] <con3000|131> reinitiating already active tasks
Nov 19 17:36:25	charon		11[IKE] <con3000|131> ISAKMP_VENDOR task
Nov 19 17:36:25	charon		11[IKE] <con3000|131> MAIN_MODE task
Nov 19 17:36:25	charon		11[ENC] <con3000|131> generating ID_PROT request 0 [ ID HASH N(INITIAL_CONTACT) ]
Nov 19 17:36:25	charon		11[NET] <con3000|131> sending packet: from <MY_SOURCE_IP>[500] to <REMOTE_IP>[500] (140 bytes)
Nov 19 17:36:25	charon		11[NET] <con3000|131> received packet: from <REMOTE_IP>[500] to <MY_SOURCE_IP>[500] (124 bytes)
Nov 19 17:36:25	charon		11[ENC] <con3000|131> parsed ID_PROT response 0 [ ID HASH ]
Nov 19 17:36:25	charon		11[IKE] <con3000|131> IKE_SA con3000[131] established between <MY_SOURCE_IP>[<MY_SOURCE_IP>]...<REMOTE_IP>[<REMOTE_IP>]
Nov 19 17:36:25	charon		11[IKE] <con3000|131> IKE_SA con3000[131] state change: CONNECTING => ESTABLISHED
Nov 19 17:36:25	charon		11[IKE] <con3000|131> scheduling reauthentication in 27934s
Nov 19 17:36:25	charon		11[IKE] <con3000|131> maximum IKE_SA lifetime 28474s
Nov 19 17:36:25	charon		11[IKE] <con3000|131> activating new tasks
Nov 19 17:36:25	charon		11[IKE] <con3000|131> activating QUICK_MODE task
Nov 19 17:36:25	charon		11[CFG] <con3000|131> configured proposals: ESP:AES_CBC_256/HMAC_SHA2_256_128/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_512_256/NO_EXT_SEQ, ESP:AES_GCM_16_128/NO_EXT_SEQ
Nov 19 17:36:25	charon		11[CFG] <con3000|131> configured proposals: ESP:AES_CBC_256/HMAC_SHA2_256_128/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_512_256/NO_EXT_SEQ, ESP:AES_GCM_16_128/NO_EXT_SEQ
Nov 19 17:36:25	charon		11[CFG] <con3000|131> proposing traffic selectors for us:
Nov 19 17:36:25	charon		11[CFG] <con3000|131> <MY_INTERESTING_TRAFFIC>|/0
Nov 19 17:36:25	charon		11[CFG] <con3000|131> proposing traffic selectors for other:
Nov 19 17:36:25	charon		11[CFG] <con3000|131> <REMOTE_INTERESTING_NET>|/0
Nov 19 17:36:25	charon		11[ENC] <con3000|131> generating QUICK_MODE request 44131316 [ HASH SA No ID ID ]
Nov 19 17:36:25	charon		11[NET] <con3000|131> sending packet: from <MY_SOURCE_IP>[500] to <REMOTE_IP>[500] (284 bytes)
Nov 19 17:36:25	charon		11[NET] <con3000|131> received packet: from <REMOTE_IP>[500] to <MY_SOURCE_IP>[500] (124 bytes)
Nov 19 17:36:25	charon		11[ENC] <con3000|131> parsed INFORMATIONAL_V1 request 2873368022 [ HASH D ]
Nov 19 17:36:25	charon		11[IKE] <con3000|131> received DELETE for ESP CHILD_SA with SPI f780296d
Nov 19 17:36:25	charon		11[IKE] <con3000|131> CHILD_SA not found, ignored
Nov 19 17:36:29	charon		11[CFG] vici client 2509 connected
Nov 19 17:36:29	charon		08[CFG] vici client 2509 registered for: list-sa
Nov 19 17:36:29	charon		07[CFG] vici client 2509 requests: list-sas
Nov 19 17:36:29	charon		07[CFG] vici client 2509 disconnected
Nov 19 17:36:29	charon		07[CFG] vici client 2510 connected
Nov 19 17:36:29	charon		08[CFG] vici client 2510 registered for: list-sa
Nov 19 17:36:29	charon		08[CFG] vici client 2510 requests: list-sas
Nov 19 17:36:29	charon		05[CFG] vici client 2510 disconnected
Nov 19 17:36:29	charon		05[IKE] <con3000|131> sending retransmit 1 of request message ID 44131316, seq 4
Nov 19 17:36:29	charon		05[NET] <con3000|131> sending packet: from <MY_SOURCE_IP>[500] to <REMOTE_IP>[500] (284 bytes)
Nov 19 17:36:34	charon		08[CFG] vici client 2511 connected
Nov 19 17:36:34	charon		08[CFG] vici client 2511 registered for: list-sa
Nov 19 17:36:34	charon		05[CFG] vici client 2511 requests: list-sas
Nov 19 17:36:34	charon		03[CFG] vici client 2511 disconnected
Nov 19 17:36:34	charon		03[CFG] vici client 2512 connected
Nov 19 17:36:34	charon		06[CFG] vici client 2512 registered for: list-sa
Nov 19 17:36:34	charon		06[CFG] vici client 2512 requests: list-sas
Nov 19 17:36:34	charon		03[CFG] vici client 2512 disconnected
Nov 19 17:36:37	charon		03[IKE] <con3000|131> sending retransmit 2 of request message ID 44131316, seq 4
Nov 19 17:36:37	charon		03[NET] <con3000|131> sending packet: from <MY_SOURCE_IP>[500] to <REMOTE_IP>[500] (284 bytes)
Nov 19 17:36:37	charon		03[KNL] creating acquire job for policy <MY_SOURCE_IP>/32|/0 === <REMOTE_IP>/32|/0 with reqid {10}
Nov 19 17:36:37	charon		03[CFG] ignoring acquire, connection attempt pending
Nov 19 17:36:40	charon		03[CFG] vici client 2513 connected
Nov 19 17:36:40	charon		03[CFG] vici client 2513 registered for: list-sa
Nov 19 17:36:40	charon		03[CFG] vici client 2513 requests: list-sas
Nov 19 17:36:40	charon		03[CFG] vici client 2513 disconnected
Nov 19 17:36:43	charon		05[CFG] vici client 2514 connected
Nov 19 17:36:43	charon		01[CFG] vici client 2514 registered for: list-sa
Nov 19 17:36:43	charon		01[CFG] vici client 2514 requests: list-sas
Nov 19 17:36:43	charon		03[CFG] vici client 2514 disconnected

          I didn't find much errors there, only:

          03[ENC] <con3000|127> received unknown vendor ID: 38:00:7c:6d:d6:5c:c8:cf:2a:ea:90:30:a6:22:81:1e

          which might relate to encryption process. At this moment I can only try to trigger phase2 only from my side, tomorrow I might have some cisco debug logs from the remote side. But the fact that it doesn't trigger phase2 establishment already indicates a problem. And it's not VTI tunnel. What else could be checked?

          1 Reply Last reply Reply Quote 0
          • jimpJ
            jimp Rebel Alliance Developer Netgate
            last edited by

            Based on the log messages, I'd say the remote side is rejecting the Phase 2 for some reason. You'll have to increase logging/debugging on that side and see what it says.

            That or try initiating in the opposite direction.

            Remember: Upvote with the 👍 button for any user/post you find to be helpful, informative, or deserving of recognition!

            Need help fast? Netgate Global Support!

            Do not Chat/PM for help!

            S 1 Reply Last reply Reply Quote 0
            • S
              shshs @jimp
              last edited by

              @jimp said in Phase 2 is not establishing:

              Based on the log messages, I'd say the remote side is rejecting the Phase 2 for some reason. You'll have to increase logging/debugging on that side and see what it says.

              Hi @jimp, what makes you think so? In my understanding if phase1 is established (which is true in this case) then ESP traffic is generated ( triggered by interesting traffic ). But I dont see any outgoing ESP packets on my end. I’m also looking for incoming ESP, but it’s not under my administration, so it will take some time to manage. I still dont understand why pfSense does not generate egress ESP. Thank you.

              1 Reply Last reply Reply Quote 0
              • jimpJ
                jimp Rebel Alliance Developer Netgate
                last edited by

                ESP is "phase 2" traffic, so you won't see it until Phase 2 is established, which still happens during the exchange on udp/500 or udp/4500.

                This section in particular is part of what makes me think it's the remote end:

                Your side sent a request for a child SA:

                Nov 19 17:36:25	charon		11[ENC] <con3000|131> generating QUICK_MODE request 44131316 [ HASH SA No ID ID ]
Nov 19 17:36:25	charon		11[NET] <con3000|131> sending packet: from <MY_SOURCE_IP>[500] to <REMOTE_IP>[500] (284 bytes)

                Though the timing looks like it received a reply, it did not. The remote side sent a command to delete a child SA (which didn't exist):

                Nov 19 17:36:25	charon		11[NET] <con3000|131> received packet: from <REMOTE_IP>[500] to <MY_SOURCE_IP>[500] (124 bytes)
Nov 19 17:36:25	charon		11[ENC] <con3000|131> parsed INFORMATIONAL_V1 request 2873368022 [ HASH D ]
Nov 19 17:36:25	charon		11[IKE] <con3000|131> received DELETE for ESP CHILD_SA with SPI f780296d
Nov 19 17:36:25	charon		11[IKE] <con3000|131> CHILD_SA not found, ignored

                Then your side retransmits the initial request with no response:

                Nov 19 17:36:29	charon		05[IKE] <con3000|131> sending retransmit 1 of request message ID 44131316, seq 4
Nov 19 17:36:29	charon		05[NET] <con3000|131> sending packet: from <MY_SOURCE_IP>[500] to <REMOTE_IP>[500] (284 bytes)

                And then it retransmits again.

                All signs point to something on the far side either ignoring your requests or failing to parse them for one reason or another.

                Remember: Upvote with the 👍 button for any user/post you find to be helpful, informative, or deserving of recognition!

                Need help fast? Netgate Global Support!

                Do not Chat/PM for help!

                1 Reply Last reply Reply Quote 1
                • S
                  shshs
                  last edited by

                  @jimp

                  You were exactly right, the issue was on remote end. Thank you very much for your help, it's good to have such experts like you here. Good luck you to you.
                  SOLVED!

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