Phase 2 is not establishing
-
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:
While sniffing traffic towards remote tunnel destination in tcpdump I see only IKE traffic, but not ESP (tcpdump -ni <ifname> host <remote_tunnel_endpoint>):
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.
-
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.
-
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?
-
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.
-
@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.
-
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.
-
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!