IPSec issues
-
Hello,
1. We have IPSec IKEv1 connection between head office and branch office. Head office has pfSense and branch office has MIkrotik Routerboard. Both has the same configurations. Phase 1 is working normal, but sometimes phase 2 becomes multiple which are the same though phase 2 lifetime hasn't expired, it creates new one.
2. When ipsec connects, there is 15 minutes difference between rekey and lifetime in phase 2. When Phase 1 lifetime is 86400 and phase lifetime is 28800 on both sides another new phase 2 is being created automatically by pfsense 1 hour 10 minutes before the current phase 2 rekey expires, however current rekey hasn't expired.
I reduced lifetime on both sides, phase 1 28800 and phase 2 3600, but it didn't change the result. I noticed that it happens when there is more than one phase 2.
I am pasting logs here for your review.
Oct 27 12:20:20 charon 13[NET] <con3000|7> sending packet: from 94.85.130.10[500] to 85.120.10.230[500] (92 bytes) Oct 27 12:20:20 charon 13[ENC] <con3000|7> generating INFORMATIONAL_V1 request 2766240837 [ HASH N(DPD_ACK) ] Oct 27 12:20:20 charon 13[IKE] <con3000|7> activating ISAKMP_DPD task Oct 27 12:20:20 charon 13[IKE] <con3000|7> activating new tasks Oct 27 12:20:20 charon 13[IKE] <con3000|7> queueing ISAKMP_DPD task Oct 27 12:20:20 charon 13[ENC] <con3000|7> parsed INFORMATIONAL_V1 request 2165248547 [ HASH N(DPD) ] Oct 27 12:20:20 charon 13[NET] <con3000|7> received packet: from 85.120.10.230[500] to 94.85.130.10[500] (92 bytes) Oct 27 12:20:19 charon 13[CHD] <con3000|7> CHILD_SA con3000{57} state change: REKEYING => REKEYED Oct 27 12:20:19 charon 13[CHD] <con3000|7> CHILD_SA con3000{58} state change: INSTALLING => INSTALLED Oct 27 12:20:19 charon 13[IKE] <con3000|7> CHILD_SA con3000{58} established with SPIs ce4c784a_i 03fbefba_o and TS 192.168.4.10/32|/0 === 192.168.1.0/24|/0 Oct 27 12:20:19 charon 13[CHD] <con3000|7> SPI 0x03fbefba, src 94.85.130.10 dst 85.120.10.230 Oct 27 12:20:19 charon 13[CHD] <con3000|7> adding outbound ESP SA Oct 27 12:20:19 charon 13[CHD] <con3000|7> SPI 0xce4c784a, src 85.120.10.230 dst 94.85.130.10 Oct 27 12:20:19 charon 13[CHD] <con3000|7> adding inbound ESP SA Oct 27 12:20:19 charon 13[CHD] <con3000|7> using HMAC_SHA1_96 for integrity Oct 27 12:20:19 charon 13[CHD] <con3000|7> using AES_CBC for encryption Oct 27 12:20:19 charon 13[CHD] <con3000|7> CHILD_SA con3000{58} state change: CREATED => INSTALLING Oct 27 12:20:19 charon 13[ENC] <con3000|7> parsed QUICK_MODE request 2929448535 [ HASH ] Oct 27 12:20:19 charon 13[NET] <con3000|7> received packet: from 85.120.10.230[500] to 94.85.130.10[500] (60 bytes) Oct 27 12:20:19 charon 13[NET] <con3000|7> sending packet: from 94.85.130.10[500] to 85.120.10.230[500] (316 bytes) Oct 27 12:20:19 charon 13[ENC] <con3000|7> generating QUICK_MODE response 2929448535 [ HASH SA No KE ID ID ] Oct 27 12:20:19 charon 13[IKE] <con3000|7> detected rekeying of CHILD_SA con3000{57} Oct 27 12:20:19 charon 13[CHD] <con3000|7> CHILD_SA con3000{57} state change: INSTALLED => REKEYING Oct 27 12:20:19 charon 13[CFG] <con3000|7> selected proposal: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ Oct 27 12:20:19 charon 13[CFG] <con3000|7> configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ Oct 27 12:20:19 charon 13[CFG] <con3000|7> received proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_1024/NO_EXT_SEQ Oct 27 12:20:19 charon 13[CFG] <con3000|7> proposal matches Oct 27 12:20:19 charon 13[CFG] <con3000|7> selecting proposal: Oct 27 12:20:19 charon 13[CFG] <con3000|7> config: 192.168.4.10/32|/0, received: 192.168.4.10/32|/0 => match: 192.168.4.10/32|/0 Oct 27 12:20:19 charon 13[CFG] <con3000|7> selecting traffic selectors for us: Oct 27 12:20:19 charon 13[CFG] <con3000|7> config: 192.168.1.0/24|/0, received: 192.168.1.0/24|/0 => match: 192.168.1.0/24|/0 Oct 27 12:20:19 charon 13[CFG] <con3000|7> selecting traffic selectors for other: Oct 27 12:20:19 charon 13[CFG] <con3000|7> found matching child config "con3000" with prio 10 Oct 27 12:20:19 charon 13[CFG] <con3000|7> candidate "con3000" with prio 5+5 Oct 27 12:20:19 charon 13[CFG] <con3000|7> 192.168.1.0/24|/0 Oct 27 12:20:19 charon 13[CFG] <con3000|7> proposing traffic selectors for other: Oct 27 12:20:19 charon 13[CFG] <con3000|7> 192.168.4.10/32|/0 Oct 27 12:20:19 charon 13[CFG] <con3000|7> proposing traffic selectors for us: Oct 27 12:20:19 charon 13[CFG] <con3000|7> looking for a child config for 192.168.4.10/32|/0 === 192.168.1.0/24|/0 Oct 27 12:20:19 charon 13[ENC] <con3000|7> parsed QUICK_MODE request 2929448535 [ HASH SA No KE ID ID ] Oct 27 12:20:19 charon 13[NET] <con3000|7> received packet: from 85.120.10.230[500] to 94.85.130.10[500] (300 bytes) Oct 27 12:20:19 charon 13[CFG] vici client 2917 disconnected Oct 27 12:20:19 charon 15[CFG] vici client 2917 requests: list-sas Oct 27 12:20:19 charon 13[CFG] vici client 2917 registered for: list-sa Oct 27 12:20:19 charon 08[CFG] vici client 2917 connected Oct 27 12:20:18 charon 15[IKE] <con1000|4> nothing to initiate Oct 27 12:20:18 charon 15[IKE] <con1000|4> activating new tasks Oct 27 12:20:18 charon 15[ENC] <con1000|4> parsed INFORMATIONAL_V1 request 2912155618 [ HASH N(DPD_ACK) ] Oct 27 12:20:18 charon 15[NET] <con1000|4> received packet: from 95.86.130.77[500] to 94.85.130.10[500] (92 bytes) Oct 27 12:20:18 charon 15[IKE] <con1000|4> nothing to initiate Oct 27 12:20:18 charon 15[IKE] <con1000|4> activating new tasks Oct 27 12:20:18 charon 15[NET] <con1000|4> sending packet: from 94.85.130.10[500] to 95.86.130.77[500] (92 bytes) Oct 27 12:20:18 charon 15[ENC] <con1000|4> generating INFORMATIONAL_V1 request 437082278 [ HASH N(DPD) ] Oct 27 12:20:18 charon 15[IKE] <con1000|4> activating ISAKMP_DPD task Oct 27 12:20:18 charon 15[IKE] <con1000|4> activating new tasks Oct 27 12:20:18 charon 15[IKE] <con1000|4> queueing ISAKMP_DPD task Oct 27 12:20:18 charon 15[IKE] <con1000|4> sending DPD request Oct 27 12:20:16 charon 15[IKE] <con2000|6> nothing to initiate Oct 27 12:20:16 charon 15[IKE] <con2000|6> activating new tasks Oct 27 12:20:16 charon 15[NET] <con2000|6> sending packet: from 94.85.130.10[500] to 95.86.133.70[500] (92 bytes) Oct 27 12:20:16 charon 15[ENC] <con2000|6> generating INFORMATIONAL_V1 request 882525495 [ HASH N(DPD_ACK) ] Oct 27 12:20:16 charon 15[IKE] <con2000|6> activating ISAKMP_DPD task Oct 27 12:20:16 charon 15[IKE] <con2000|6> activating new tasks Oct 27 12:20:16 charon 15[IKE] <con2000|6> queueing ISAKMP_DPD task
-
3. Today I created IKEv2 with another branch. First times it worked okay, when phase 2 rekey expires, it created automatically new phase 2 and deleted the old one. It worked okay until then, when phase 1 lifetime expired, it created new phase 1 and deleted old phase 1, but it recreated the same phase 2s, however phase 2s rekey hasn't expired. But in IKEv1 when phase 1 expires, it creates new phase 1, but doesn't create phase 2 which ones rekey has not expired.
I like pfSense, but this issues tires me. I am pasting the logs of ipsec with IKEv2 for your review.
Oct 28 19:59:15 charon 01[CFG] vici client 2899 disconnected Oct 28 19:59:15 charon 12[CFG] vici client 2899 requests: list-sas Oct 28 19:59:15 charon 01[CFG] vici client 2899 registered for: list-sa Oct 28 19:59:15 charon 15[CFG] vici client 2899 connected Oct 28 19:59:15 charon 12[IKE] <con1000|1> nothing to initiate Oct 28 19:59:15 charon 12[IKE] <con1000|1> activating new tasks Oct 28 19:59:15 charon 12[ENC] <con1000|1> parsed INFORMATIONAL_V1 request 470720582 [ HASH N(DPD_ACK) ] Oct 28 19:59:15 charon 12[NET] <con1000|1> received packet: from 95.86.130.77[500] to 94.85.130.10[500] (92 bytes) Oct 28 19:59:15 charon 12[IKE] <con1000|1> nothing to initiate Oct 28 19:59:15 charon 12[IKE] <con1000|1> activating new tasks Oct 28 19:59:15 charon 12[NET] <con1000|1> sending packet: from 94.85.130.10[500] to 95.86.130.77[500] (92 bytes) Oct 28 19:59:15 charon 12[ENC] <con1000|1> generating INFORMATIONAL_V1 request 911759279 [ HASH N(DPD) ] Oct 28 19:59:15 charon 12[IKE] <con1000|1> activating ISAKMP_DPD task Oct 28 19:59:15 charon 12[IKE] <con1000|1> activating new tasks Oct 28 19:59:15 charon 12[IKE] <con1000|1> queueing ISAKMP_DPD task Oct 28 19:59:15 charon 12[IKE] <con1000|1> sending DPD request Oct 28 19:59:10 charon 12[NET] <con2000|181> sending packet: from 94.85.130.10[4500] to 85.145.31.16[4500] (80 bytes) Oct 28 19:59:10 charon 12[ENC] <con2000|181> generating INFORMATIONAL response 9 [ ] Oct 28 19:59:10 charon 12[ENC] <con2000|181> parsed INFORMATIONAL request 9 [ ] Oct 28 19:59:10 charon 12[NET] <con2000|181> received packet: from 85.145.31.16[4500] to 94.85.130.10[4500] (128 bytes) Oct 28 19:59:10 charon 12[CFG] vici client 2898 disconnected Oct 28 19:59:10 charon 12[CFG] vici client 2898 requests: list-sas Oct 28 19:59:10 charon 12[CFG] vici client 2898 registered for: list-sa Oct 28 19:59:10 charon 06[CFG] vici client 2898 connected Oct 28 19:59:05 charon 15[IKE] <con1000|1> nothing to initiate Oct 28 19:59:05 charon 15[IKE] <con1000|1> activating new tasks Oct 28 19:59:05 charon 15[ENC] <con1000|1> parsed INFORMATIONAL_V1 request 2011893979 [ HASH N(DPD_ACK) ] Oct 28 19:59:05 charon 15[NET] <con1000|1> received packet: from 95.86.130.77[500] to 94.85.130.10[500] (92 bytes) Oct 28 19:59:05 charon 15[IKE] <con1000|1> nothing to initiate Oct 28 19:59:05 charon 15[IKE] <con1000|1> activating new tasks Oct 28 19:59:05 charon 15[NET] <con1000|1> sending packet: from 94.85.130.10[500] to 95.86.130.77[500] (92 bytes) Oct 28 19:59:05 charon 15[ENC] <con1000|1> generating INFORMATIONAL_V1 request 3186446868 [ HASH N(DPD) ] Oct 28 19:59:05 charon 15[IKE] <con1000|1> activating ISAKMP_DPD task Oct 28 19:59:05 charon 15[IKE] <con1000|1> activating new tasks Oct 28 19:59:05 charon 15[IKE] <con1000|1> queueing ISAKMP_DPD task Oct 28 19:59:05 charon 15[IKE] <con1000|1> sending DPD request Oct 28 19:59:04 charon 15[CFG] vici client 2897 disconnected Oct 28 19:59:04 charon 15[CFG] vici client 2897 requests: list-sas Oct 28 19:59:04 charon 15[CFG] vici client 2897 registered for: list-sa Oct 28 19:59:04 charon 07[CFG] vici client 2897 connected Oct 28 19:59:00 charon 06[NET] <con2000|181> sending packet: from 94.85.130.10[4500] to 85.145.31.16[4500] (80 bytes) Oct 28 19:59:00 charon 06[ENC] <con2000|181> generating INFORMATIONAL response 8 [ ] Oct 28 19:59:00 charon 06[ENC] <con2000|181> parsed INFORMATIONAL request 8 [ ] Oct 28 19:59:00 charon 06[NET] <con2000|181> received packet: from 85.145.31.16[4500] to 94.85.130.10[4500] (96 bytes) Oct 28 19:58:59 charon 06[CFG] vici client 2896 disconnected Oct 28 19:58:59 charon 14[CFG] vici client 2896 requests: list-sas Oct 28 19:58:59 charon 14[CFG] vici client 2896 registered for: list-sa Oct 28 19:58:59 charon 07[CFG] vici client 2896 connected Oct 28 19:58:55 charon 06[IKE] <con1000|1> nothing to initiate Oct 28 19:58:55 charon 06[IKE] <con1000|1> activating new tasks Oct 28 19:58:55 charon 06[ENC] <con1000|1> parsed INFORMATIONAL_V1 request 288515128 [ HASH N(DPD_ACK) ]
-
Does it impact traffic flow?
-
@emammadov said in IPSec issues:
85.120.10.230
Yes, there is. When phase 1 in IKEv2 expires, it creates new phase 1, but recreates phase 2s and duplicates them. I have two phase 2, when phase 1 expired and created again, it created only one phase 1.
Oct 29 14:22:40 charon 09[CFG] vici client 2045 disconnected Oct 29 14:22:40 charon 09[CFG] vici client 2045 requests: list-sas Oct 29 14:22:40 charon 06[CFG] vici client 2045 registered for: list-sa Oct 29 14:22:40 charon 10[CFG] vici client 2045 connected Oct 29 14:22:39 charon 09[NET] <con3000|5> sending packet: from 94.85.130.10[4500] to 85.120.10.230[4500] (80 bytes) Oct 29 14:22:39 charon 09[ENC] <con3000|5> generating CREATE_CHILD_SA response 8 [ N(TS_UNACCEPT) ] Oct 29 14:22:39 charon 09[IKE] <con3000|5> failed to establish CHILD_SA, keeping IKE_SA Oct 29 14:22:39 charon 09[IKE] <con3000|5> traffic selectors 192.168.4.10/32|/0 === 192.168.1.0/24|/0 inacceptable Oct 29 14:22:39 charon 09[CFG] <con3000|5> looking for a child config for 192.168.4.10/32|/0 === 192.168.1.0/24|/0 Oct 29 14:22:39 charon 09[ENC] <con3000|5> parsed CREATE_CHILD_SA request 8 [ No KE SA TSi TSr ] Oct 29 14:22:39 charon 09[NET] <con3000|5> received packet: from 85.120.10.230[4500] to 94.85.130.10[4500] (496 bytes) Oct 29 14:22:37 charon 09[IKE] <con1000|3> nothing to initiate Oct 29 14:22:37 charon 09[IKE] <con1000|3> activating new tasks Oct 29 14:22:37 charon 09[ENC] <con1000|3> parsed INFORMATIONAL_V1 request 870049060 [ HASH N(DPD_ACK) ] Oct 29 14:22:37 charon 09[NET] <con1000|3> received packet: from 95.86.130.77[500] to 94.85.130.10[500] (92 bytes) Oct 29 14:22:37 charon 09[IKE] <con1000|3> nothing to initiate Oct 29 14:22:37 charon 09[IKE] <con1000|3> activating new tasks Oct 29 14:22:37 charon 09[NET] <con1000|3> sending packet: from 94.85.130.10[500] to 95.86.130.77[500] (92 bytes) Oct 29 14:22:37 charon 09[ENC] <con1000|3> generating INFORMATIONAL_V1 request 2055258912 [ HASH N(DPD) ] Oct 29 14:22:37 charon 09[IKE] <con1000|3> activating ISAKMP_DPD task Oct 29 14:22:37 charon 09[IKE] <con1000|3> activating new tasks Oct 29 14:22:37 charon 09[IKE] <con1000|3> queueing ISAKMP_DPD task Oct 29 14:22:37 charon 09[IKE] <con1000|3> sending DPD request Oct 29 14:22:37 charon 10[NET] <con2000|2> sending packet: from 94.85.130.10[4500] to 95.86.133.70[4500] (80 bytes) Oct 29 14:22:37 charon 10[ENC] <con2000|2> generating INFORMATIONAL response 1430 [ ] Oct 29 14:22:37 charon 10[ENC] <con2000|2> parsed INFORMATIONAL request 1430 [ ] Oct 29 14:22:37 charon 10[NET] <con2000|2> received packet: from 95.86.133.70[4500] to 94.85.130.10[4500] (112 bytes) Oct 29 14:22:35 charon 10[CFG] vici client 2044 disconnected Oct 29 14:22:35 charon 15[CFG] vici client 2044 requests: list-sas Oct 29 14:22:35 charon 15[CFG] vici client 2044 registered for: list-sa Oct 29 14:22:35 charon 09[CFG] vici client 2044 connected Oct 29 14:22:34 charon 10[NET] <con3000|5> sending packet: from 94.85.130.10[4500] to 85.120.10.230[4500] (80 bytes) Oct 29 14:22:34 charon 10[ENC] <con3000|5> generating INFORMATIONAL response 7 [ ] Oct 29 14:22:34 charon 10[ENC] <con3000|5> parsed INFORMATIONAL request 7 [ ] Oct 29 14:22:34 charon 10[NET] <con3000|5> received packet: from 85.120.10.230[4500] to 94.85.130.10[4500] (128 bytes) Oct 29 14:22:30 charon 12[CFG] vici client 2043 disconnected Oct 29 14:22:30 charon 12[CFG] vici client 2043 requests: list-sas Oct 29 14:22:30 charon 12[CFG] vici client 2043 registered for: list-sa Oct 29 14:22:30 charon 10[CFG] vici client 2043 connected Oct 29 14:22:27 charon 01[IKE] <con1000|3> nothing to initiate Oct 29 14:22:27 charon 01[IKE] <con1000|3> activating new tasks Oct 29 14:22:27 charon 01[ENC] <con1000|3> parsed INFORMATIONAL_V1 request 4109594201 [ HASH N(DPD_ACK) ]
I switched from IKEv2 to IKEv1, but when ipsec connects there double the same phase 2.
-
But does it impact traffic flow across the VPN?
-
I ping remote server, it is going okay, sometimes it shows "Request timed out". As you can see it duplicates phase 2.
-
Those are harmless. They are rekeyed tunnels. They are not the cause of any traffic flow issues. They will disappear when their lifetimes expire. They are there in case the other side sends traffic to the rekeyed SAs so it can be decrypted.
Running the shell command
ipsec statusall
will reveal them as rekeyed.If you have traffic problems over the VPN I would not spend any more time on that and focus on other reasons you might be seeing what you are seeing.
-
Thank you. The problem is, when phase 2 rekey expires it creates a new one, but it also duplicates phase 2. Then there are two same phase 2, they expire and create new same ones.I have 4 ipsec connections, one with Palo Alto, the rest with Mikrotik routers. Ipsec with Palo Alto and one of Mikrotik is working normal. Though the rest two Mikrotik have the same configurations as others, we see these issues.
You think it is because of Mikrotik?
What if I disable rekey? Then it will not work?
Why there are 15 minutes difference between rekey and life?
Is it okay if I add margin time for example 5 seconds, because of decreasing 15 minutes to 5 seconds?
Why phase1 in IKEv2 expires, it removes all phase 2 and creates phase 2 again? This doesn't happen in IKEv1. -
@emammadov said in IPSec issues:
Thank you. The problem is, when phase 2 rekey expires it creates a new one, but it also duplicates phase 2. Then there are two same phase 2, they expire and create new same ones.I have 4 ipsec connections, one with Palo Alto, the rest with Mikrotik routers. Ipsec with Palo Alto and one of Mikrotik is working normal. Though the rest two Mikrotik have the same configurations as others, we see these issues.
Right. That is normal.
You think it is because of Mikrotik?
No.
What if I disable rekey? Then it will not work?
No. I would not do that.
Why there are 15 minutes difference between rekey and life?
The rekey is set randomly a short interval before the lifetime. This is perfectly normal.
Is it okay if I add margin time for example 5 seconds, because of decreasing 15 minutes to 5 seconds?
I would leave it alone.
Why phase1 in IKEv2 expires, it removes all phase 2 and creates phase 2 again? This doesn't happen in IKEv1.
Because that's how it works. You can see if enabling Make-Before-Break in VPN > IPsec, Advanced helps but read the notes there and understand that will affect all IKEv2 tunnels.
Keep in mind that the IPsec > Status screen can be delayed by several seconds.
Again, those rekeyed SAs are probably NOT the source of any problems you are having as long as the new SA is established on rekey. You are probably chasing a ghost.
-
Ok. I have another question. There is ipsec IKEv2 connection. Phase 1 and two phase 2. Phase 1 and two phase 2 is ip. It is also seems to be up in Status / IPSec. But in the dashboard, I mean the home page of pfsense, only one phase 2 tunnel seems to be up.
-
If you look at the actual phase 2 it is probably combined into one with both sets of addresses.
-
In IKEv1, each phase 2 seems separate. Why it is not so in Ikev2. Is it possible do it as Ikev1 in the next update? Because it makes user to get confused.
-
Because IKEv2 can combine them.
If you do not like this behavior you can try enabling Split Connections on that tunnel.
Some devices, notably the Cisco ASA, do not allow multiple traffic selectors on one SA so that option was added.
-
Thank you very much.
-
If I enable Make before Break in Advanced settings for IKEv2 in pfsense, then does the remote side should support this? pfSense is responder and Mikrotik is initiator in ipsec. I noticed that Make before Break option is available in Mikrotik settings. Will it create a problem in connection?
-
No idea what the Mikrotik will do but, yes, both sides need to support it. Set a maintenance window, try it, and see.