Problems after 2.2.1 upgrade not passing traffic after rekeying
-
That is exactly the same problem that I was having. Once I installed the oldsa patch the problem went completely away. I was loosing the tunnels several times a day but since installing the patch on Wednesday, the tunnels have been up continuously. Did you upgrade from 2.2 or from a 2.1x installation?
I also note that you did report that traffic started flowing after some 40 minutes. My experience with the problem was that once the problem occurred traffic did not flow again until some event caused the tunnels to be completely rebuilt. Do you see anything in the log (on either end) around the time the connection started working on its own?
-
Hi
@kitdavis:Did you upgrade from 2.2 or from a 2.1x installation?
Yes, upgrade from 2.1.5 directly to 2.2.1
btw. I have a CARP-ClusterPatch already on both machines installed and completely rebooted.
Now I have a tunnel witch does not come back..
Here I have approx 50 entries for the same subnet and the state "Rekey: active"Do you see anything in the log (on either end) around the time the connection started working on its own?
This is the log from the other end (Sophos)
015:04:08-08:42:35 VPN1 [26730]: "S_REF_iZBHPvPFxu_0" #1173: sending encrypted notification INVALID_ID_INFORMATION to xxx.xxx.xxx.xxx:500
2015:04:08-08:42:36 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1171: max number of retransmissions (2) reached STATE_QUICK_I1. No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
2015:04:08-08:42:36 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1171: starting keying attempt 180 of an unlimited number
2015:04:08-08:42:36 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1176: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP to replace #1171 {using isakmp#15}
2015:04:08-08:42:37 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1176: peer client ID returned doesn't match my proposal
2015:04:08-08:42:37 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1176: sending encrypted notification INVALID_ID_INFORMATION to xxx.xxx.xxx.xxx:500
2015:04:08-08:42:39 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1174: peer client ID returned doesn't match my proposal
2015:04:08-08:42:39 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1174: sending encrypted notification INVALID_ID_INFORMATION to xxx.xxx.xxx.xxx:500
2015:04:08-08:42:46 VPN1 [26730]: "S_REF_iZBHPvPFxu_0" #15: ignoring informational payload, type INVALID_HASH_INFORMATION
2015:04:08-08:42:54 VPN1 [26730]: "S_REF_iZBHPvPFxu_0" #1175: peer client ID returned doesn't match my proposal
2015:04:08-08:42:54 VPN1 [26730]: "S_REF_iZBHPvPFxu_0" #1175: sending encrypted notification INVALID_ID_INFORMATION to xxx.xxx.xxx.xxx:500
2015:04:08-08:43:06 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1176: peer client ID returned doesn't match my proposal
2015:04:08-08:43:06 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1176: sending encrypted notification INVALID_ID_INFORMATION to xxx.xxx.xxx.xxx:500
2015:04:08-08:43:11 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1172: max number of retransmissions (2) reached STATE_QUICK_I1. No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
2015:04:08-08:43:11 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1172: starting keying attempt 184 of an unlimited number
2015:04:08-08:43:11 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1177: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP to replace #1172 {using isakmp#15}
2015:04:08-08:43:12 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1177: peer client ID returned doesn't match my proposal
2015:04:08-08:43:12 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1177: sending encrypted notification INVALID_ID_INFORMATION to xxx.xxx.xxx.xxx:500
2015:04:08-08:43:15 VPN1 [26730]: "S_REF_iZBHPvPFxu_0" #1173: max number of retransmissions (2) reached STATE_QUICK_I1
2015:04:08-08:43:15 VPN1 [26730]: "S_REF_iZBHPvPFxu_0" #1173: starting keying attempt 190 of an unlimited number
2015:04:08-08:43:15 VPN1 [26730]: "S_REF_iZBHPvPFxu_0" #1178: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP to replace #1173 {using isakmp#15}
2015:04:08-08:43:15 VPN1 [26730]: "S_REF_iZBHPvPFxu_0" #1178: peer client ID returned doesn't match my proposal
2015:04:08-08:43:15 VPN1 [26730]: "S_REF_iZBHPvPFxu_0" #1178: sending encrypted notification INVALID_ID_INFORMATION to xxx.xxx.xxx.xxx:500
2015:04:08-08:43:19 VPN1 [26730]: "S_REF_iZBHPvPFxu_1" #1174: max number of retransmissions (2) reached STATE_QUICK_I1. No acceptable response to our first Quick Mode message: perhaps peer likes no proposal-> this messages loops
From my site the log (stronswan) is useless (Thread already opened)
-
Hello,
at night an other tunnel was going down.
Also Sophos:
2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | length: 32 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | transform number: 1 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | transform ID: AES_CBC 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | ******parse ISAKMP IPsec DOI attribute: 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | af+type: KEY_LENGTH 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | length/value: 256 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | ******parse ISAKMP IPsec DOI attribute: 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | af+type: AUTH_ALGORITHM 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | length/value: 7 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | [7 is HMAC_SHA2_512] 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | ******parse ISAKMP IPsec DOI attribute: 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | af+type: GROUP_DESCRIPTION 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | length/value: 15 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | [15 is MODP_3072] 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | ******parse ISAKMP IPsec DOI attribute: 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | af+type: ENCAPSULATION_MODE 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | length/value: 1 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | [1 is ENCAPSULATION_MODE_TUNNEL] 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | ******parse ISAKMP IPsec DOI attribute: 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | af+type: SA_LIFE_TYPE 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | length/value: 1 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | [1 is SA_LIFE_TYPE_SECONDS] 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | ******parse ISAKMP IPsec DOI attribute: 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | af+type: SA_LIFE_DURATION 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | length/value: 3600 2015:04:09-08:08:55 VPN-Router-2 pluto[19193]: | kernel_alg_esp_enc_ok(12,256): alg_id=12, alg_ivlen=8, alg_minbits=128, alg_maxbits=256, res=0, ret=1 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | our client is subnet 10.15.1.0/24 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | our client protocol/port is 0/0 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | peer client is subnet 0.0.0.0/0 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | peer client protocol/port is 0/0 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: "S_REF_IpsSitS2sintrabi_0" #1384: peer client ID returned doesn't match my proposal 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: "S_REF_IpsSitS2sintrabi_0" #1384: sending encrypted notification INVALID_ID_INFORMATION to xxx.xxx.xxx.xxx:500 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | **emit ISAKMP Message: 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | initiator cookie: 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | 82 4e 24 97 2d 64 22 57 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | responder cookie: 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | 88 a3 33 40 36 b2 c2 3b 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | next payload type: ISAKMP_NEXT_HASH 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | ISAKMP version: ISAKMP Version 1.0 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | exchange type: ISAKMP_XCHG_INFO 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | flags: ISAKMP_FLAG_ENCRYPTION 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | message ID: a3 29 8b ea 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | ***emit ISAKMP Hash Payload: 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | next payload type: ISAKMP_NEXT_N 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | emitting 64 zero bytes of HASH into ISAKMP Hash Payload 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | emitting length of ISAKMP Hash Payload: 68 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | ***emit ISAKMP Notification Payload: 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | next payload type: ISAKMP_NEXT_NONE 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | DOI: ISAKMP_DOI_IPSEC 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | protocol ID: 1 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | SPI size: 0 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | Notify Message Type: INVALID_ID_INFORMATION 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | emitting 0 raw bytes of spi into ISAKMP Notification Payload 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | spi 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | emitting length of ISAKMP Notification Payload: 12 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | emitting length of ISAKMP Message: 108 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | state transition function for STATE_QUICK_I1 failed: INVALID_ID_INFORMATION 2015:04:09-08:08:56 VPN-Router-2 pluto[19193]: | next event EVENT_RETRANSMIT in 7 seconds for #1383on my side I have approx 40 child SA entries. It seems that the expired tunnel does not remove.
-
Check the new sticky note about prefer older SA
-
Anyone who's seeing rekeying issues along these lines, please upgrade to 2.2.2 and report back. In addition to the prefer old SAs fix, the version of strongswan has been upgraded, among the other IPsec improvements.
Anyone who can replicate problems along these lines with SAs piling up on 2.2.2, please PM me, it's not something that's easily replicable that I've seen and I want to make sure any outstanding issues get fixed.
-
I'm not sure this is the same problem, but we've upgraded to 2.2.2 and we're still having an issue that appears to be related to rekeying. (The issue seemed to start when we upgraded to 2.2.1.) I was able to work around the problem by checking the "Disable rekey" IPsec phase 1 option, but I wonder how much security we're losing, as a result.
We've got a peer-to-peer VPN connection to a vendor that's using a Cisco firewall, and they had a process that needed an uninterrupted connection to one of our servers for about 36 hours. The problem was that, after an hour or two, the connection would drop and the process would need to be started over. Using couple of scripts I wrote, I discovered that, every hour or two, I would receive no ping replies for 20-30 seconds, and those times lined up with times the pfSense was rekeying the connection. (The IPsec log contained the line "creating rekey job for ESP CHILD_SA with SPI".)
I've read that the most recent version of pfSense can hide the rekeying time, as long as you're using IKEv2. We're using IKEv1, so I've emailed the administrator for the remote firewall to make that change, but he hasn't got back to me, yet.
-
Hello,
Now I have updated my CARP-Cluster to 2.2.2 and I have still this issue!! >:(
Since the change to strongswan, the main component of a firewall is awful in any partitions.
The log ist still unreadable. At racoon century I was able to explain the network administrator on the other site what was going wrong. Now I ask the same administrator to send me his logfiles for troubleshooting. This is so frustrating.
At the past I could count on that no underdone main module were implemented.Here my log (dump)… Sorry.. I am not able to filter the important parts because I does not know which entry belongs to which tunnel.
Apr 25 16:33:07 charon: 09[ENC] <con18|474>parsed INFORMATIONAL response 119 [ ] Apr 25 16:33:07 charon: 09[NET] <con18|474>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (96 bytes) Apr 25 16:33:07 charon: 09[ENC] <con12000|4>parsed INFORMATIONAL_V1 request 1564653583 [ HASH N(DPD_ACK) ] Apr 25 16:33:07 charon: 09[NET] <con12000|4>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (92 bytes) Apr 25 16:33:07 charon: 09[NET] <con12000|4>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (92 bytes) Apr 25 16:33:07 charon: 09[ENC] <con12000|4>generating INFORMATIONAL_V1 request 118977497 [ HASH N(DPD) ] Apr 25 16:33:07 charon: 09[IKE] <con12000|4>sending DPD request Apr 25 16:33:07 charon: 09[IKE] <con12000|4>sending DPD request Apr 25 16:33:07 charon: 09[NET] <con15|29>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (80 bytes) Apr 25 16:33:07 charon: 09[ENC] <con15|29>generating INFORMATIONAL response 46 [ ] Apr 25 16:33:07 charon: 09[ENC] <con15|29>parsed INFORMATIONAL request 46 [ ] Apr 25 16:33:07 charon: 09[NET] <con15|29>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (80 bytes) Apr 25 16:33:06 charon: 09[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:33:06 charon: 09[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:33:06 charon: 09[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI b9c00479 Apr 25 16:33:06 charon: 09[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI b9c00479 Apr 25 16:33:06 charon: 09[ENC] <con13000|31>parsed INFORMATIONAL_V1 request 3119178486 [ HASH D ] Apr 25 16:33:06 charon: 09[NET] <con13000|31>received packet: from xxx.xxx.xxx.xxx[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:33:06 charon: 09[NET] <con18|474>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (96 bytes) Apr 25 16:33:06 charon: 09[ENC] <con18|474>generating INFORMATIONAL request 119 [ ] Apr 25 16:33:06 charon: 09[IKE] <con18|474>sending DPD request Apr 25 16:33:06 charon: 09[IKE] <con18|474>sending DPD request Apr 25 16:33:04 charon: 06[ENC] <con20000|648>parsed INFORMATIONAL_V1 request 2197749233 [ HASH N(DPD_ACK) ] Apr 25 16:33:04 charon: 06[NET] <con20000|648>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (140 bytes) Apr 25 16:33:04 charon: 06[NET] <con20000|648>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (140 bytes) Apr 25 16:33:04 charon: 06[ENC] <con20000|648>generating INFORMATIONAL_V1 request 349939385 [ HASH N(DPD) ] Apr 25 16:33:04 charon: 06[IKE] <con20000|648>sending DPD request Apr 25 16:33:04 charon: 06[IKE] <con20000|648>sending DPD request Apr 25 16:33:04 charon: 06[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:33:04 charon: 06[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:33:04 charon: 06[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 378d036a Apr 25 16:33:04 charon: 06[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 378d036a Apr 25 16:33:04 charon: 06[ENC] <con13000|31>parsed INFORMATIONAL_V1 request 1152623439 [ HASH D ] Apr 25 16:33:04 charon: 06[NET] <con13000|31>received packet: from xxx.xxx.xxx.xxx[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:33:04 charon: 10[ENC] <con17000|241>parsed INFORMATIONAL_V1 request 3703510351 [ HASH N(DPD_ACK) ] Apr 25 16:33:04 charon: 10[NET] <con17000|241>received packet: from zzz.zzz.zzz.zzz[4500] to my.local.pfsense.IP[4500] (140 bytes) Apr 25 16:33:04 charon: 10[NET] <con17000|241>sending packet: from my.local.pfsense.IP[4500] to zzz.zzz.zzz.zzz[4500] (140 bytes) Apr 25 16:33:04 charon: 10[ENC] <con17000|241>generating INFORMATIONAL_V1 request 1792492415 [ HASH N(DPD) ] Apr 25 16:33:04 charon: 10[IKE] <con17000|241>sending DPD request Apr 25 16:33:04 charon: 10[IKE] <con17000|241>sending DPD request Apr 25 16:33:03 charon: 10[NET] <con23000|27>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (92 bytes) Apr 25 16:33:03 charon: 10[ENC] <con23000|27>generating INFORMATIONAL_V1 request 1349975187 [ HASH N(DPD_ACK) ] Apr 25 16:33:03 charon: 10[ENC] <con23000|27>parsed INFORMATIONAL_V1 request 1558984787 [ HASH N(DPD) ] Apr 25 16:33:03 charon: 10[NET] <con23000|27>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (92 bytes) Apr 25 16:33:03 charon: 10[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:33:03 charon: 10[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:33:03 charon: 10[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 000c2541 Apr 25 16:33:03 charon: 10[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 000c2541 Apr 25 16:33:03 charon: 10[ENC] <con13000|31>parsed INFORMATIONAL_V1 request 2617589153 [ HASH D ] Apr 25 16:33:03 charon: 10[NET] <con13000|31>received packet: from xxx.xxx.xxx.xxx[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:33:02 charon: 09[NET] <con3000|240>sending packet: from my.local.pfsense.IP[4500] to zzz.zzz.zzz.zzz[4500] (140 bytes) Apr 25 16:33:02 charon: 09[ENC] <con3000|240>generating INFORMATIONAL_V1 request 2996761664 [ HASH N(DPD_ACK) ] Apr 25 16:33:02 charon: 09[ENC] <con3000|240>parsed INFORMATIONAL_V1 request 636958179 [ HASH N(DPD) ] Apr 25 16:33:02 charon: 09[NET] <con3000|240>received packet: from zzz.zzz.zzz.zzz[4500] to my.local.pfsense.IP[4500] (140 bytes) Apr 25 16:33:00 charon: 08[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:33:00 charon: 08[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:33:00 charon: 08[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 7538a87d Apr 25 16:33:00 charon: 08[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 7538a87d Apr 25 16:33:00 charon: 08[ENC] <con13000|31>parsed INFORMATIONAL_V1 request 2092199335 [ HASH D ] Apr 25 16:33:00 charon: 08[NET] <con13000|31>received packet: from xxx.xxx.xxx.xxx[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:33:00 charon: 08[ENC] <con19000|468>parsed INFORMATIONAL_V1 request 1334491019 [ HASH N(DPD_ACK) ] Apr 25 16:33:00 charon: 08[NET] <con19000|468>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (140 bytes) Apr 25 16:32:59 charon: 08[NET] <con19000|468>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (140 bytes) Apr 25 16:32:59 charon: 08[ENC] <con19000|468>generating INFORMATIONAL_V1 request 774513974 [ HASH N(DPD) ] Apr 25 16:32:59 charon: 08[IKE] <con19000|468>sending DPD request Apr 25 16:32:59 charon: 08[IKE] <con19000|468>sending DPD request Apr 25 16:32:59 charon: 08[IKE] <con6000|22>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 08[IKE] <con6000|22>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 08[IKE] <con6000|22>received DELETE for ESP CHILD_SA with SPI 08e3d441 Apr 25 16:32:59 charon: 08[IKE] <con6000|22>received DELETE for ESP CHILD_SA with SPI 08e3d441 Apr 25 16:32:59 charon: 08[ENC] <con6000|22>parsed INFORMATIONAL_V1 request 3262730041 [ HASH D ] Apr 25 16:32:59 charon: 08[NET] <con6000|22>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:32:59 charon: 08[IKE] <con2000|21>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 08[IKE] <con2000|21>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 08[IKE] <con2000|21>received DELETE for ESP CHILD_SA with SPI 639da0e0 Apr 25 16:32:59 charon: 08[IKE] <con2000|21>received DELETE for ESP CHILD_SA with SPI 639da0e0 Apr 25 16:32:59 charon: 08[ENC] <con2000|21>parsed INFORMATIONAL_V1 request 2113800731 [ HASH D ] Apr 25 16:32:59 charon: 08[NET] <con2000|21>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:32:59 charon: 08[IKE] <con14000|26>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 08[IKE] <con14000|26>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 08[IKE] <con14000|26>received DELETE for ESP CHILD_SA with SPI 1dcd3820 Apr 25 16:32:59 charon: 08[IKE] <con14000|26>received DELETE for ESP CHILD_SA with SPI 1dcd3820 Apr 25 16:32:59 charon: 08[ENC] <con14000|26>parsed INFORMATIONAL_V1 request 2629950835 [ HASH D ] Apr 25 16:32:59 charon: 08[NET] <con14000|26>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:32:59 charon: 08[ENC] <con22000|1178>parsed INFORMATIONAL_V1 request 3940481499 [ HASH N(DPD_ACK) ] Apr 25 16:32:59 charon: 08[NET] <con22000|1178>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (92 bytes) Apr 25 16:32:59 charon: 08[NET] <con22000|1178>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (92 bytes) Apr 25 16:32:59 charon: 08[ENC] <con22000|1178>generating INFORMATIONAL_V1 request 1777631898 [ HASH N(DPD) ] Apr 25 16:32:59 charon: 08[IKE] <con22000|1178>sending DPD request Apr 25 16:32:59 charon: 08[IKE] <con22000|1178>sending DPD request Apr 25 16:32:59 charon: 08[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 08[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 08[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 751f79f0 Apr 25 16:32:59 charon: 08[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 751f79f0 Apr 25 16:32:59 charon: 08[ENC] <con13000|31>parsed INFORMATIONAL_V1 request 1546787869 [ HASH D ] Apr 25 16:32:59 charon: 08[NET] <con13000|31>received packet: from xxx.xxx.xxx.xxx[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:32:59 charon: 12[IKE] <con10000|19>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 12[IKE] <con10000|19>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 12[IKE] <con10000|19>received DELETE for ESP CHILD_SA with SPI ec4f316b Apr 25 16:32:59 charon: 12[IKE] <con10000|19>received DELETE for ESP CHILD_SA with SPI ec4f316b Apr 25 16:32:59 charon: 12[ENC] <con10000|19>parsed INFORMATIONAL_V1 request 2207769426 [ HASH D ] Apr 25 16:32:59 charon: 12[NET] <con10000|19>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:32:59 charon: 12[IKE] <con1000|28>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 12[IKE] <con1000|28>CHILD_SA not found, ignored Apr 25 16:32:59 charon: 12[IKE] <con1000|28>received DELETE for ESP CHILD_SA with SPI a130a72c Apr 25 16:32:59 charon: 12[IKE] <con1000|28>received DELETE for ESP CHILD_SA with SPI a130a72c Apr 25 16:32:59 charon: 12[ENC] <con1000|28>parsed INFORMATIONAL_V1 request 1709002469 [ HASH D ] Apr 25 16:32:59 charon: 12[NET] <con1000|28>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:32:58 charon: 12[IKE] <con25000|80>CHILD_SA not found, ignored Apr 25 16:32:58 charon: 12[IKE] <con25000|80>CHILD_SA not found, ignored Apr 25 16:32:58 charon: 12[IKE] <con25000|80>received DELETE for ESP CHILD_SA with SPI 3a6b46c9 Apr 25 16:32:58 charon: 12[IKE] <con25000|80>received DELETE for ESP CHILD_SA with SPI 3a6b46c9 Apr 25 16:32:58 charon: 12[ENC] <con25000|80>parsed INFORMATIONAL_V1 request 1361005290 [ HASH D ] Apr 25 16:32:58 charon: 12[NET] <con25000|80>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:32:57 charon: 12[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:32:57 charon: 12[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:32:57 charon: 12[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 7561bf6d Apr 25 16:32:57 charon: 12[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 7561bf6d Apr 25 16:32:57 charon: 12[ENC] <con13000|31>parsed INFORMATIONAL_V1 request 1229997925 [ HASH D ] Apr 25 16:32:57 charon: 12[NET] <con13000|31>received packet: from xxx.xxx.xxx.xxx[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:32:57 charon: 12[ENC] <con18|474>parsed INFORMATIONAL response 118 [ ] Apr 25 16:32:57 charon: 12[NET] <con18|474>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (96 bytes) Apr 25 16:32:57 charon: 12[ENC] <con12000|4>parsed INFORMATIONAL_V1 request 143804701 [ HASH N(DPD_ACK) ] Apr 25 16:32:57 charon: 12[NET] <con12000|4>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (92 bytes) Apr 25 16:32:57 charon: 12[NET] <con12000|4>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (92 bytes) Apr 25 16:32:57 charon: 12[ENC] <con12000|4>generating INFORMATIONAL_V1 request 478577563 [ HASH N(DPD) ] Apr 25 16:32:57 charon: 12[IKE] <con12000|4>sending DPD request Apr 25 16:32:57 charon: 12[IKE] <con12000|4>sending DPD request Apr 25 16:32:57 charon: 11[NET] <con15|29>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (80 bytes) Apr 25 16:32:57 charon: 11[ENC] <con15|29>generating INFORMATIONAL response 45 [ ] Apr 25 16:32:57 charon: 11[ENC] <con15|29>parsed INFORMATIONAL request 45 [ ] Apr 25 16:32:57 charon: 11[NET] <con15|29>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (80 bytes) Apr 25 16:32:56 charon: 11[NET] <con18|474>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (96 bytes) Apr 25 16:32:56 charon: 11[ENC] <con18|474>generating INFORMATIONAL request 118 [ ] Apr 25 16:32:56 charon: 11[IKE] <con18|474>sending DPD request Apr 25 16:32:56 charon: 11[IKE] <con18|474>sending DPD request Apr 25 16:32:56 charon: 11[ENC] <con4000|11>parsed INFORMATIONAL_V1 request 1381363991 [ HASH N(DPD_ACK) ] Apr 25 16:32:56 charon: 11[NET] <con4000|11>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (140 bytes) Apr 25 16:32:56 charon: 11[NET] <con4000|11>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (140 bytes) Apr 25 16:32:56 charon: 11[ENC] <con4000|11>generating INFORMATIONAL_V1 request 3504403619 [ HASH N(DPD) ] Apr 25 16:32:56 charon: 11[IKE] <con4000|11>sending DPD request Apr 25 16:32:56 charon: 11[IKE] <con4000|11>sending DPD request Apr 25 16:32:55 charon: 11[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:32:55 charon: 11[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:32:55 charon: 11[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 3afe4036 Apr 25 16:32:55 charon: 11[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 3afe4036 Apr 25 16:32:55 charon: 11[ENC] <con13000|31>parsed INFORMATIONAL_V1 request 3137469033 [ HASH D ] Apr 25 16:32:55 charon: 11[NET] <con13000|31>received packet: from xxx.xxx.xxx.xxx[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:32:55 charon: 11[NET] <3382> sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (56 bytes) Apr 25 16:32:55 charon: 11[ENC] <3382> generating INFORMATIONAL_V1 request 2652241747 [ N(NO_PROP) ] Apr 25 16:32:55 charon: 11[IKE] <3382> no proposal found Apr 25 16:32:55 charon: 11[IKE] <3382> no proposal found Apr 25 16:32:55 charon: 11[CFG] <3382> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1536 Apr 25 16:32:55 charon: 11[CFG] <3382> received proposals: IKE:AES_CBC_256/HMAC_MD5_96/PRF_HMAC_MD5/MODP_1536 Apr 25 16:32:55 charon: 11[IKE] <3382> 46.252.128.242 is initiating a Main Mode IKE_SA Apr 25 16:32:55 charon: 11[IKE] <3382> 46.252.128.242 is initiating a Main Mode IKE_SA Apr 25 16:32:55 charon: 11[IKE] <3382> received DPD vendor ID Apr 25 16:32:55 charon: 11[IKE] <3382> received DPD vendor ID Apr 25 16:32:55 charon: 11[IKE] <3382> received XAuth vendor ID Apr 25 16:32:55 charon: 11[IKE] <3382> received XAuth vendor ID Apr 25 16:32:55 charon: 11[IKE] <3382> received Cisco Unity vendor ID Apr 25 16:32:55 charon: 11[IKE] <3382> received Cisco Unity vendor ID Apr 25 16:32:55 charon: 11[IKE] <3382> received strongSwan vendor ID Apr 25 16:32:55 charon: 11[IKE] <3382> received strongSwan vendor ID Apr 25 16:32:55 charon: 11[ENC] <3382> parsed ID_PROT request 0 [ SA V V V V ] Apr 25 16:32:55 charon: 11[NET] <3382> received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (156 bytes) Apr 25 16:32:55 charon: 11[ENC] <con5000|76>parsed INFORMATIONAL_V1 request 2479835611 [ HASH N(DPD_ACK) ] Apr 25 16:32:55 charon: 11[NET] <con5000|76>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (92 bytes) Apr 25 16:32:55 charon: 11[NET] <con5000|76>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (92 bytes) Apr 25 16:32:55 charon: 11[ENC] <con5000|76>generating INFORMATIONAL_V1 request 3637565574 [ HASH N(DPD) ] Apr 25 16:32:55 charon: 11[IKE] <con5000|76>sending DPD request Apr 25 16:32:55 charon: 11[IKE] <con5000|76>sending DPD request Apr 25 16:32:54 charon: 14[ENC] <con17000|241>parsed INFORMATIONAL_V1 request 96340431 [ HASH N(DPD_ACK) ] Apr 25 16:32:54 charon: 14[NET] <con17000|241>received packet: from zzz.zzz.zzz.zzz[4500] to my.local.pfsense.IP[4500] (140 bytes) Apr 25 16:32:54 charon: 14[NET] <con17000|241>sending packet: from my.local.pfsense.IP[4500] to zzz.zzz.zzz.zzz[4500] (140 bytes) Apr 25 16:32:54 charon: 14[ENC] <con17000|241>generating INFORMATIONAL_V1 request 1621594452 [ HASH N(DPD) ] Apr 25 16:32:54 charon: 14[IKE] <con17000|241>sending DPD request Apr 25 16:32:54 charon: 14[IKE] <con17000|241>sending DPD request Apr 25 16:32:53 charon: 14[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:32:53 charon: 14[IKE] <con13000|31>CHILD_SA not found, ignored Apr 25 16:32:53 charon: 14[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 57f38c63 Apr 25 16:32:53 charon: 14[IKE] <con13000|31>received DELETE for ESP CHILD_SA with SPI 57f38c63 Apr 25 16:32:53 charon: 14[ENC] <con13000|31>parsed INFORMATIONAL_V1 request 868575397 [ HASH D ] Apr 25 16:32:53 charon: 14[NET] <con13000|31>received packet: from xxx.xxx.xxx.xxx[500] to my.local.pfsense.IP[500] (124 bytes) Apr 25 16:32:52 charon: 14[NET] <con11000|33>sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (92 bytes) Apr 25 16:32:52 charon: 14[ENC] <con11000|33>generating INFORMATIONAL_V1 request 2554034778 [ HASH N(DPD_ACK) ] Apr 25 16:32:52 charon: 14[ENC] <con11000|33>parsed INFORMATIONAL_V1 request 1589669651 [ HASH N(DPD) ] Apr 25 16:32:52 charon: 14[NET] <con11000|33>received packet: from zzz.zzz.zzz.zzz[500] to my.local.pfsense.IP[500] (92 bytes) Apr 25 16:32:52 charon: 14[NET] <con3000|240>sending packet: from my.local.pfsense.IP[4500] to zzz.zzz.zzz.zzz[4500] (140 bytes) Apr 25 16:32:52 charon: 14[ENC] <con3000|240>generating INFORMATIONAL_V1 request 2219395581 [ HASH N(DPD_ACK) ] Apr 25 16:32:52 charon: 14[ENC] <con3000|240>parsed INFORMATIONAL_V1 request 2540775577 [ HASH N(DPD) ] Apr 25 16:32:52 charon: 14[NET] <con3000|240>received packet: from zzz.zzz.zzz.zzz[4500] to my.local.pfsense.IP[4500] (140 bytes) Apr 25 16:32:51 charon: 14[NET] <con13000|31>sending packet: from my.local.pfsense.IP[500] to xxx.xxx.xxx.xxx[500] (140 bytes) Apr 25 16:32:51 charon: 14[ENC] <con13000|31>generating INFORMATIONAL_V1 request 176562984 [ HASH N(DPD_ACK) ] Apr 25 16:32:51 charon: 14[ENC] <con13000|31>parsed INFORMATIONAL_V1 request 2204584495 [ HASH N(DPD) ] Apr 25 16:32:51 charon: 14[NET] <con13000|31>received packet: from xxx.xxx.xxx.xxx[500] to my.local.pfsense.IP[500] (140 bytes) Apr 25 16:32:50 charon: 14[NET] <3381> sending packet: from my.local.pfsense.IP[500] to zzz.zzz.zzz.zzz[500] (56 bytes) Apr 25 16:32:50 charon: 14[ENC] <3381> generating INFORMATIONAL_V1 request 3355800620 [ N(NO_PROP) ] Apr 25 16:32:50 charon: 14[IKE] <3381> no proposal found Apr 25 16:32:50 charon: 14[IKE] <3381> no proposal found Apr 25 16:32:50 charon: 14[CFG] <3381> configured proposals: IKE:AES_CBC_256/HMAC_SHA2_512_256/PRF_HMAC_SHA2_512/MODP_1536 Apr 25 16:32:50 charon: 14[CFG] <3381> received proposals: IKE:AES_CBC_256/HMAC_SHA2_512_256/PRF_HMAC_SHA2_512/MODP_4096 Apr 25 16:32:50 charon: 14[IKE] <3381> 87.193.208.114 is initiating a Main Mode IKE_SA Apr 25 16:32:50 charon: 14[IKE] <3381> 87.193.208.114 is initiating a Main Mode IKE_SA Apr 25 16:32:50 charon: 14[IKE] <3381> received draft-ietf-ipsec-nat-t-ike-00 vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received draft-ietf-ipsec-nat-t-ike-00 vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received draft-ietf-ipsec-nat-t-ike-02\n vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received draft-ietf-ipsec-nat-t-ike-02\n vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received draft-ietf-ipsec-nat-t-ike-02 vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received draft-ietf-ipsec-nat-t-ike-02 vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received draft-ietf-ipsec-nat-t-ike-03 vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received draft-ietf-ipsec-nat-t-ike-03 vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received NAT-T (RFC 3947) vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received NAT-T (RFC 3947) vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received DPD vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received DPD vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received XAuth vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received XAuth vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received Cisco Unity vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received Cisco Unity vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received strongSwan vendor ID Apr 25 16:32:50 charon: 14[IKE] <3381> received strongSwan vendor ID</con13000|31></con13000|31></con13000|31></con13000|31></con3000|240></con3000|240></con3000|240></con3000|240></con11000|33></con11000|33></con11000|33></con11000|33></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con17000|241></con17000|241></con17000|241></con17000|241></con17000|241></con17000|241></con5000|76></con5000|76></con5000|76></con5000|76></con5000|76></con5000|76></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con4000|11></con4000|11></con4000|11></con4000|11></con4000|11></con4000|11></con18|474></con18|474></con18|474></con18|474></con15|29></con15|29></con15|29></con15|29></con12000|4></con12000|4></con12000|4></con12000|4></con12000|4></con12000|4></con18|474></con18|474></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con25000|80></con25000|80></con25000|80></con25000|80></con25000|80></con25000|80></con1000|28></con1000|28></con1000|28></con1000|28></con1000|28></con1000|28></con10000|19></con10000|19></con10000|19></con10000|19></con10000|19></con10000|19></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con22000|1178></con22000|1178></con22000|1178></con22000|1178></con22000|1178></con22000|1178></con14000|26></con14000|26></con14000|26></con14000|26></con14000|26></con14000|26></con2000|21></con2000|21></con2000|21></con2000|21></con2000|21></con2000|21></con6000|22></con6000|22></con6000|22></con6000|22></con6000|22></con6000|22></con19000|468></con19000|468></con19000|468></con19000|468></con19000|468></con19000|468></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con3000|240></con3000|240></con3000|240></con3000|240></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con23000|27></con23000|27></con23000|27></con23000|27></con17000|241></con17000|241></con17000|241></con17000|241></con17000|241></con17000|241></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con20000|648></con20000|648></con20000|648></con20000|648></con20000|648></con20000|648></con18|474></con18|474></con18|474></con18|474></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con13000|31></con15|29></con15|29></con15|29></con15|29></con12000|4></con12000|4></con12000|4></con12000|4></con12000|4></con12000|4></con18|474></con18|474>xxx.xxx.xxx.xxx IP-Address of the tunnel which is not working (screenshots)
zzz.zzz.zzz.zzz other addressesLet me know If you need further information… :-\
-
Ruddimaster: I emailed you at the address you registered on the forum using. I'd like to take a look at your system to find the source of that issue, can arrange specifics there.
-
Hi Chris,
@cmb:
Ruddimaster: I emailed you at the address you registered on the forum using. I'd like to take a look at your system to find the source of that issue, can arrange specifics there.
That would be nice…
At weekend, all IPSec-Tunnels were stable.
One tunnel shows many entries again. But for traffic this VPN is stable...
After update to 2.2.2 I have additional empty Algo entires.
Btw. the lifetime is 3600 (1h)
-
I emailed Ruddimaster but wanted to post here as well for others. If you're having rekeying issues, especially with multiple P2s, applying this change and rebooting may fix.
https://github.com/pfsense/pfsense/commit/afd0c1f2c9c46eaa8e496e98bea8a8e0887d504f
