pfSense Gold Subscription

Author Topic: Another IPSEC issue  (Read 21122 times)

0 Members and 1 Guest are viewing this topic.

Offline kitdavis

  • Jr. Member
  • **
  • Posts: 79
  • Karma: +3/-0
    • View Profile
Another IPSEC issue
« on: January 11, 2015, 08:43:11 pm »
Back in December I reported a couple of IPSEC problems.   Most of these problems were resolved, but the initial problem still exists:

When PFSense is started, the tunnels all are connected and work fine even with intermittent losses of connectivity.   However after 24+ hours, I notice that a number of the tunnels report that they are disconnected.   Clicking on the connect button does not restore the connection.  In the 2.2 log I see:

Jan 11 22:38:46   charon: 04[NET] sending packet: from 69.69.69.83[500] to 142.142.142.142[500] (40 bytes)
Jan 11 22:38:46   charon: 04[ENC] generating INFORMATIONAL_V1 request 2656656085 [ N(NO_PROP) ]
Jan 11 22:38:46   charon: 04[IKE] no IKE config found for 69.69.69.83...142.142.142.142, sending NO_PROPOSAL_CHOSEN
Jan 11 22:38:46   charon: 04[IKE] <14428> no IKE config found for 69.69.69.83...142.142.142.142, sending NO_PROPOSAL_CHOSEN
Jan 11 22:38:46   charon: 04[ENC] parsed ID_PROT request 0 [ SA V V ]
Jan 11 22:38:46   charon: 04[NET] received packet: from 142.142.142.142[500] to 69.69.69.83[500] (128 bytes)

On the 2.15 side I see:
    racoon: [ynys canso]: [69.60.66.83] ERROR: phase2 negotiation failed due to time up waiting for phase1 [Remote Side not responding]. ESP 69.69.69.83[0]->142.142.142.142[0]
Jan 11 22:39:59    racoon: [yso]: [69.69.69.83] ERROR: notification NO-PROPOSAL-CHOSEN received in unencrypted informational exchange.
Jan 11 22:39:49    racoon: [yso]: [69.69.69.83] ERROR: notification NO-PROPOSAL-CHOSEN received in unencrypted informational exchange.
Jan 11 22:39:39    racoon: [yso]: [69.69.69.83] ERROR: notification NO-PROPOSAL-CHOSEN received in unencrypted informational exchange.
Jan 11 22:39:29    racoon: [yso]: [69.69.69.83] ERROR: notification NO-PROPOSAL-CHOSEN received in unencrypted informational exchange.
Jan 11 22:39:29    racoon: INFO: begin Identity Protection mode.
Jan 11 22:39:29    racoon: [yso]: INFO: initiate new phase 1 negotiation: 142.142.142.142[500]<=>69.69.69.83[500]

If I restart the 2.2 pFsense box then all of the tunnels are restored and will work for the next 24 hours.

Offline cmb

  • Hero Member
  • *****
  • Posts: 11230
  • Karma: +893/-7
    • View Profile
    • Chris Buechler
Re: Another IPSEC issue
« Reply #1 on: January 11, 2015, 09:41:40 pm »
Have you upgraded to the latest available? Some this this past week were in flux in IPsec, you'll want to be on the latest available snapshot.

If you already are, or upgrade and it continues, could you open that back up where I can reach it?

Offline kitdavis

  • Jr. Member
  • **
  • Posts: 79
  • Karma: +3/-0
    • View Profile
Re: Another IPSEC issue
« Reply #2 on: January 12, 2015, 04:52:10 am »
As long as I keep updating to the newest snapshoot each day, the problem never occurs - (in this case, I stayed on Friday's snapshot and the problem started on Sunday.    I will upgrade to the newest snapshot this morning and then leave that in place and notify you when/if the tunnels are lost.




















Offline ermal

  • Hero Member
  • *****
  • Posts: 3832
  • Karma: +85/-5
    • View Profile
Re: Another IPSEC issue
« Reply #3 on: January 12, 2015, 05:34:06 am »
This might be related to rekey requirments even being disabled or some mismatch with the other side.

Can you see if the rekey times shown on the status->ipsec are approximately 24 hours.

Offline kitdavis

  • Jr. Member
  • **
  • Posts: 79
  • Karma: +3/-0
    • View Profile
Re: Another IPSEC issue
« Reply #4 on: January 12, 2015, 06:41:27 am »
Reuath is shown as being 7 hours.   

Offline ermal

  • Hero Member
  • *****
  • Posts: 3832
  • Karma: +85/-5
    • View Profile
Re: Another IPSEC issue
« Reply #5 on: January 12, 2015, 07:31:58 am »
Code: [Select]
Jan 11 22:38:46   charon: 04[IKE] <14428> no IKE config found for 69.69.69.83...142.142.142.142, sending NO_PROPOSAL_CHOSEN

Looking at this again, do you have anything special in your configuration? Dyndns?
Also does it try to do re-authentication with agressive mode? If yes, does strongswan log anything more useful there?
Normally you should increase the IKE log level to detect this.

Offline kitdavis

  • Jr. Member
  • **
  • Posts: 79
  • Karma: +3/-0
    • View Profile
Re: Another IPSEC issue
« Reply #6 on: January 12, 2015, 07:49:05 am »
No, everything is pretty simple - the wild card is there are 18 tunnels, and a rather unstable connection (fixed wireless) so connectivity is often lost several times during the day. 

Chris changed the debug levels (I think) when we were working on the other IPSEC problem.   Both IKE and IKE Child were set to Diag - I moved the log level to Highest. All of the tunnels were originally set to use aggressive mode but I have moved most of them to main over the last few days and should have the rest migrated today.   The "broken" tunnels this morning were a mix of aggressive and main.   I upgraded to the latest snapshot earlier today, so I expect the problem will occur some time late tomorrow.

Offline cmb

  • Hero Member
  • *****
  • Posts: 11230
  • Karma: +893/-7
    • View Profile
    • Chris Buechler
Re: Another IPSEC issue
« Reply #7 on: January 12, 2015, 07:51:25 pm »
This happened today to me as well. Seems specific to IKEv1, but doesn't appear to be universal to all IKEv1. Have you noticed anything common to the ones that are doing that for you vs. the ones that aren't? Or do the affected ones change in your case?

I dropped my P1 lifetime down to an hour in hopes of being able to replicate it more quickly. Seems to coincide with rekeying of P1, at least if I remember your configs. You have a P1 lifetime of 86400 on the affected connections, and something less than that as the P2 lifetime?

I was thinking it was something new given it's never happened to me before nor do I seem to find it from anyone else, but the symptoms might match what you'd posted in December. The fact at the time it was only higher numbered connections doing it, I figured it was part of the other overall issue we'd fixed with the identifiers there that fixed the general problem you had. Is it still the higher ID ones that have an issue?
« Last Edit: January 12, 2015, 08:08:48 pm by cmb »

Offline ermal

  • Hero Member
  • *****
  • Posts: 3832
  • Karma: +85/-5
    • View Profile
Re: Another IPSEC issue
« Reply #8 on: January 13, 2015, 03:52:34 am »
Can you please put this systcl under system->advanced->tunables
net.inet.ipsec.debug = 0xffffff

After that tell me when the issue happens if you see anything on the output of dmesg -a or paste the last lines from it here.

Offline ermal

  • Hero Member
  • *****
  • Posts: 3832
  • Karma: +85/-5
    • View Profile
Re: Another IPSEC issue
« Reply #9 on: January 13, 2015, 05:38:52 am »
Also can you please give me the output of
netstat -f inet -sp esp

when you have the issue?

Offline cmb

  • Hero Member
  • *****
  • Posts: 11230
  • Karma: +893/-7
    • View Profile
    • Chris Buechler
Re: Another IPSEC issue
« Reply #10 on: January 14, 2015, 09:39:29 pm »
We backed down to strongswan 5.2.1 to see if that fixes this issue. I upgraded your system kitdavis and am keeping an eye on its logs. Earlier today, it started exhibiting the same symptoms about 12 hours after the upgrade. So we should know one way or another within the next 12 hours or so.

Offline swix

  • Jr. Member
  • **
  • Posts: 26
  • Karma: +1/-0
    • View Profile
Re: Another IPSEC issue - same situation here
« Reply #11 on: January 19, 2015, 09:02:41 am »
I have a similar issue as described here, and it it still seems to be the case on latest snapshot (2.2-RC (amd64) built on Fri Jan 16 11:53:08 CST 2015 FreeBSD 10.1-RELEASE-p4 on PC-Engines APU Board). 

2 IPSEC Tunnels with respectively 2 and 4 phase 2 entries.  And after a few hours, some of the phases 2 are not reachable anymore, while the others are still there. For example users connected to the LAN cannot connect to the tunneled IP's while users connected via OpenVPN to our network still can.

Stopping and restarting the IPSEC service "fixes" the issue (clicking on the Restart IPSEC icon doesn't).   

I could not reproduce it yet, but the logfile says approximately this around the time of a disconnect:

Code: [Select]
Jan 19 15:43:16 pf charon: 02[ENC] generating INFORMATIONAL_V1 request 3956259368 [ HASH N(DPD) ]
Jan 19 15:43:16 pf charon: 02[NET] sending packet: from ip1[500] to ip2[500] (92 bytes)
Jan 19 15:43:16 pf charon: 02[NET] received packet: from ip2[500] to ip1[500] (92 bytes)
Jan 19 15:43:16 pf charon: 02[ENC] parsed INFORMATIONAL_V1 request 735452451 [ HASH N(DPD_ACK) ]
Jan 19 15:43:20 pf charon: 02[NET] received packet: from ip3[500] to ip1[500] (364 bytes)
Jan 19 15:43:20 pf charon: 02[ENC] parsed QUICK_MODE request 141741184 [ HASH SA No KE ID ID ]
Jan 19 15:43:20 pf charon: 02[ENC] received HASH payload does not match
Jan 19 15:43:20 pf charon: 02[IKE] <con2000|13> integrity check failed
Jan 19 15:43:20 pf charon: 02[IKE] integrity check failed
Jan 19 15:43:20 pf charon: 02[ENC] generating INFORMATIONAL_V1 request 1348227468 [ HASH N(INVAL_HASH) ]
Jan 19 15:43:20 pf charon: 02[NET] sending packet: from ip1[500] to ip3[500] (76 bytes)
Jan 19 15:43:20 pf charon: 02[IKE] <con2000|13> QUICK_MODE request with message ID 141741184 processing failed
Jan 19 15:43:20 pf charon: 02[IKE] QUICK_MODE request with message ID 141741184 processing failed
Jan 19 15:43:21 pf charon: 02[IKE] <con2000|13> sending DPD request
Jan 19 15:43:21 pf charon: 02[IKE] sending DPD request
Jan 19 15:43:21 pf charon: 02[ENC] generating INFORMATIONAL_V1 request 3461990251 [ HASH N(DPD) ]
Jan 19 15:43:21 pf charon: 02[NET] sending packet: from ip1[500] to ip3[500] (92 bytes)
Jan 19 15:43:21 pf charon: 02[NET] received packet: from ip3[500] to ip1[500] (92 bytes)
Jan 19 15:43:21 pf charon: 02[ENC] parsed INFORMATIONAL_V1 request 3939011389 [ HASH N(DPD_ACK) ]
Jan 19 15:43:21 pf charon: 02[NET] received packet: from ip3[500] to ip1[500] (364 bytes)
Jan 19 15:43:21 pf charon: 02[ENC] parsed QUICK_MODE request 3030064237 [ HASH SA No KE ID ID ]
Jan 19 15:43:21 pf charon: 02[IKE] <con2000|13> detected rekeying of CHILD_SA con2000{4}
Jan 19 15:43:21 pf charon: 02[IKE] detected rekeying of CHILD_SA con2000{4}
Jan 19 15:43:21 pf charon: 02[ENC] generating QUICK_MODE response 3030064237 [ HASH SA No KE ID ID ]
Jan 19 15:43:21 pf charon: 02[NET] sending packet: from ip1[500] to ip3[500] (380 bytes)
Jan 19 15:43:21 pf charon: 02[NET] received packet: from ip3[500] to ip1[500] (76 bytes)
Jan 19 15:43:21 pf charon: 02[ENC] parsed INFORMATIONAL_V1 request 2447641578 [ HASH N(INVAL_ID) ]
Jan 19 15:43:21 pf charon: 02[IKE] <con2000|13> received INVALID_ID_INFORMATION error notify
Jan 19 15:43:21 pf charon: 02[IKE] received INVALID_ID_INFORMATION error notify
Jan 19 15:43:21 pf charon: 02[IKE] <con2000|13> received INVALID_ID_INFORMATION error notify
Jan 19 15:43:21 pf charon: 02[IKE] received INVALID_ID_INFORMATION error notify
Jan 19 15:43:26 pf charon: 16[NET] received packet: from ip3[500] to ip1[500] (364 bytes)
Jan 19 15:43:26 pf charon: 16[ENC] parsed QUICK_MODE request 84872551 [ HASH SA No KE ID ID ]
Jan 19 15:43:26 pf charon: 16[IKE] <con2000|13> detected rekeying of CHILD_SA con2000{4}
Jan 19 15:43:26 pf charon: 16[IKE] detected rekeying of CHILD_SA con2000{4}
Jan 19 15:43:26 pf charon: 16[ENC] generating QUICK_MODE response 84872551 [ HASH SA No KE ID ID ]
Jan 19 15:43:26 pf charon: 16[NET] sending packet: from ip1[500] to ip3[500] (380 bytes)
Jan 19 15:43:26 pf charon: 16[NET] received packet: from ip3[500] to ip1[500] (76 bytes)
Jan 19 15:43:26 pf charon: 16[ENC] parsed INFORMATIONAL_V1 request 4148709878 [ HASH N(INVAL_ID) ]
Jan 19 15:43:26 pf charon: 16[IKE] <con2000|13> received INVALID_ID_INFORMATION error notify
Jan 19 15:43:26 pf charon: 16[IKE] received INVALID_ID_INFORMATION error notify
Jan 19 15:43:26 pf charon: 16[IKE] <con2000|13> received INVALID_ID_INFORMATION error notify

To be continued !   I will try to tune the rekey/reauth settings later this week.  But with pfSense 2.1.x everything was very stable, so it seems quite 2.2-related to me.

Offline ermal

  • Hero Member
  • *****
  • Posts: 3832
  • Karma: +85/-5
    • View Profile
Re: Another IPSEC issue
« Reply #12 on: January 20, 2015, 02:52:29 am »
What is the other side of the tunnel?

Offline swix

  • Jr. Member
  • **
  • Posts: 26
  • Karma: +1/-0
    • View Profile
Re: Another IPSEC issue
« Reply #13 on: January 21, 2015, 04:03:58 pm »
Hi Ermal and thanks for your answer :

What is the other side of the tunnel?

Not a pfsense for sure, but I will need to ask (in both case these are large companies with expensive setups).   Regards.

Offline ermal

  • Hero Member
  • *****
  • Posts: 3832
  • Karma: +85/-5
    • View Profile
Re: Another IPSEC issue
« Reply #14 on: January 21, 2015, 04:06:31 pm »
Which DH group you using?