IPSEC Problems
-
I have a pfsense implementation that has ipsec tunnels to 17 different networks with pfsense firewalls inplace. These connections are mostly utilized for monitoring, via zabbix, equipment behind each of the firewalls, so there is a light volume of traffic sent over these connections.
Due to the nature of the setup (fixed long range wireless) quality of service is poor and the connections can be broken several times a day for a few minutes resulting in a need to re-establish connectivitiy. This setup has been working for the past 3 or 4 years across multiple versions with no serious problems.
After upgrading to the 2.2 Release candidate, the tunnels are initially all established and active for up to 48 hours - however after loosing and re-establishing the connections multiple times many of the connections fail. When Pfsense starts, the dashboard widget for IPSEC shows 17 active tunnels and 0 inactive tunnels However, when the problem occurs, the dashboard widget shows only 7 active tunnels and 0 inactive tunnels. Checking the status of the tunnels shows normal status for the 7 active tunnels and the other 10 just show as "disconnected" If I look at the IPSEC page, the active tunnels are the first 7 listed on the page and the disconnected tunnels are the last 10. Clicking on the Connect Button does not result in a connection.
The IPSEC log is very active, however the following entries appear regularly:
Dec 21 14:45:20 charon: 08[KNL] unable to query SAD entry with SPI 0eeb0121: No such file or directory (2)
Dec 21 14:45:20 charon: 08[KNL] unable to query SAD entry with SPI 0cdc9537: No such file or directory (2)
Dec 21 14:45:20 charon: 08[KNL] unable to query SAD entry with SPI 0d94efe7: No such file or directory (2)
(repeated 47 more times)This is followed by: (111.111.111.111 is the end point of the disconnected tunnel)
Dec 21 14:45:20 charon: 08[NET] received packet: from 111.111.111.111[500] to 222.222.222.222[500] (368 bytes)
Dec 21 14:45:20 charon: 08[ENC] parsed AGGRESSIVE request 0 [ SA KE No ID V V V V V V ]
Dec 21 14:45:20 charon: 08[IKE] <18729> no IKE config found for 222.222.222.222…111.111.111.111, sending NO_PROPOSAL_CHOSEN
Dec 21 14:45:20 charon: 08[IKE] no IKE config found for 222.222.222.222…111.111.111.111, sending NO_PROPOSAL_CHOSEN
Dec 21 14:45:20 charon: 08[ENC] generating INFORMATIONAL_V1 request 1899503199 [ N(NO_PROP) ]
Dec 21 14:45:20 charon: 08[NET] sending packet: from 222.222.222.222[500] to 111.111.111.111[500] (40 bytes)I also note that the when hovering over the connect button for the disconnected tunnels, the first entry shows (192.168.1.1/diag_ipsec.php?act=connect&ikeid=10 the second is ikeid 11 etc. The entries that do connect all have ikeids under 10. (probably just a coincidence)
-
At the other end of the connection I see the following:
Dec 20 17:23:42 racoon: [MXXX YXXX]: [222.222.222.222] INFO: Hashing 222.222.222.222[500] with algo #1
Dec 20 17:23:42 racoon: [Self]: [111.111.111.111] INFO: Hashing 1111.111.111.111[500] with algo #1
Dec 20 17:23:42 racoon: INFO: Adding xauth VID payload.
Dec 20 17:23:46 racoon: NOTIFY: the packet is retransmitted by 222.222.222.222[500] (1).
Dec 20 17:23:53 racoon: NOTIFY: the packet is retransmitted by 222.222.222.222[500] (1).
Dec 20 17:24:06 racoon: NOTIFY: the packet is retransmitted by 222.222.222.222[500] (1).
Dec 20 17:24:30 racoon: NOTIFY: the packet is retransmitted by 222.222.222.222[500] (1).
Dec 20 17:24:32 racoon: ERROR: phase1 negotiation failed due to time up. 10433a4740788da4:11cccbd07a686bad -
Which snapshot is this?
-
The Release candidate dated - Dec 09 09:46:36 CST 2014
-
There have been various things changed/fixed in the time since the early 2.2-RC release. It will be easiest to diagnose the issue/s if you update to the latest 2.2-RC snapshot, then report what symptoms you have.
-
I upgraded to pfSense-Full-Update-2.2-RC-amd64-20141220-1507 on the 21st and I am experiencing the exact same symptoms - 10 of the tunnels show disconnected, the connect button does not re-establish the connection and a similar error appears in the log:
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 04af269a: No such file or directory (2)
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 0d243ba4: No such file or directory (2)
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 03e0bcda: No such file or directory (2)
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 02f79aa6: No such file or directory (2)
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 0d0c69dd: No such file or directory (2)
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 0207921f: No such file or directory (2)
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 087c490f: No such file or directory (2)
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 01026338: No such file or directory (2)
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 00072247: No such file or directory (2)
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 0fb23a8d: No such file or directory (2)
Dec 23 07:34:36 charon: 12[KNL] unable to query SAD entry with SPI 0c676842: No such file or directory (2)
Dec 23 07:34:38 charon: 12[NET] received packet: from 34.34.34.34[500] to 111.111.111.111[500] (84 bytes)
Dec 23 07:34:38 charon: 12[ENC] parsed INFORMATIONAL_V1 request 3768348861 [ HASH N(DPD) ]
Dec 23 07:34:38 charon: 12[ENC] generating INFORMATIONAL_V1 request 3661510268 [ HASH N(DPD_ACK) ]
Dec 23 07:34:38 charon: 12[NET] sending packet: from 111.111.111.111[500] to 34.34.34.34[500] (84 bytes)
Dec 23 07:34:39 charon: 14[IKE] <con8|13830>sending retransmit 2 of response message ID 0, seq 1
Dec 23 07:34:39 charon: 14[IKE] sending retransmit 2 of response message ID 0, seq 1
Dec 23 07:34:39 charon: 14[NET] sending packet: from 111.111.111.111[500] to 66.66.66.66[500] (416 bytes)
Dec 23 07:34:40 charon: 14[NET] received packet: from 142.177.207.38[500] to 69.60.66.83[500] (84 bytes)
Dec 23 07:34:40 charon: 14[ENC] parsed INFORMATIONAL_V1 request 4130208874 [ HASH N(DPD) ]
Dec 23 07:34:40 charon: 14[ENC] generating INFORMATIONAL_V1 request 279634980 [ HASH N(DPD_ACK) ]
Dec 23 07:34:40 charon: 14[NET] sending packet: from 111.111.111.111[500] to 38.38.38.38[500] (84 bytes)
Dec 23 07:34:41 charon: 14[NET] received packet: from 42.42.42.42[500] to 111.111.111.111[500] (368 bytes)
Dec 23 07:34:41 charon: 14[ENC] parsed AGGRESSIVE request 0 [ SA KE No ID V V V V V V ]
Dec 23 07:34:41 charon: 14[IKE] <13832> no IKE config found for 111.111.111.111…42.42.42.42, sending NO_PROPOSAL_CHOSEN
Dec 23 07:34:41 charon: 14[IKE] no IKE config found for 111.111.111.111…42.42.42.42, sending NO_PROPOSAL_CHOSEN
Dec 23 07:34:41 charon: 14[ENC] generating INFORMATIONAL_V1 request 403123786 [ N(NO_PROP) ]
Dec 23 07:34:41 charon: 14[NET] sending packet: from 111.111.111.111[500] to 42.42.42.42[500] (40 bytes)
Dec 23 07:34:42 charon: 14[NET] received packet: from 42.42.42.42[500] to 111.111.111.111[500] (372 bytes)
Dec 23 07:34:42 charon: 14[ENC] parsed AGGRESSIVE request 0 [ SA KE No ID V V V V V V ]
Dec 23 07:34:42 charon: 14[IKE] <13833> no IKE config found for 111.111.111.111…42.42.42.42, sending NO_PROPOSAL_CHOSEN
Dec 23 07:34:42 charon: 14[IKE] no IKE config found for 111.111.111.111…42.42.42.42, sending NO_PROPOSAL_CHOSEN
Dec 23 07:34:42 charon: 14[ENC] generating INFORMATIONAL_V1 request 3608187401 [ N(NO_PROP) ]If I reboot pfSense then the tunnels will again work for the next 24-48 hours.</con8|13830>
-
I'm still seeing the problem in the December 28 build. At first the tunnels work but after 24 hours or so they - just show up as disconnected and can not be restarted.
The log is full of the same set of messages:
Dec 29 07:55:10 charon: 02[NET] sending packet: from 69.69.69.83[500] to 22.77.2.2[500] (40 bytes)
Dec 29 07:55:10 charon: 02[ENC] generating INFORMATIONAL_V1 request 4290582802 [ N(NO_PROP) ]
Dec 29 07:55:10 charon: 02[IKE] no IKE config found for 69.69.69.83…22.77.2.2, sending NO_PROPOSAL_CHOSEN
Dec 29 07:55:10 charon: 02[IKE] <13155> no IKE config found for 69.69.69.83…22.77.2.2, sending NO_PROPOSAL_CHOSEN
Dec 29 07:55:10 charon: 02[ENC] parsed AGGRESSIVE request 0 [ SA KE No ID V V V V V V ]
Dec 29 07:55:10 charon: 02[NET] received packet: from 22.77.2.26[500] to 69.69.69.83[500] (372 bytes)
Dec 29 07:55:10 charon: 02[NET] sending packet: from 69.60.66.83[500] to 22.76.1.2[500] (40 bytes)
Dec 29 07:55:10 charon: 02[ENC] generating INFORMATIONAL_V1 request 3199455391 [ N(NO_PROP) ]
Dec 29 07:55:10 charon: 02[IKE] no IKE config found for 69.69.69.83…22.76.1.2, sending NO_PROPOSAL_CHOSEN
Dec 29 07:55:10 charon: 02[IKE] <13154> no IKE config found for 69.69.69.83…22.76.1.2, sending NO_PROPOSAL_CHOSENA reboot brings up the tunnels again.
-
Additionally, I am finding additional problems with the IPSEC connections:
I have three tunnels to remote end points that with the exception of sites specific information (IP addresses) that are exact duplicates of each other, even to the point of running the same hardware. All three sites are running version 2.15.
Since upgrading to the 2.2 RC stream on my local firewall, 1 of the remote connections works without fail.
The second site establishes a connection, but the no data can be passed across the tunnel to the remote side. As can be seen in the first screen print the tunnel shows it is active but the child entry shows no packets being passed.
The third site also establishes the tunnel however it creates 10 child entries all with no data being passed. (second screen print). This tunnel fails and then recycles after about 10 minutes. During the process I find many of the following message in the IPSEC Log:
Dec 29 11:02:23 charon: 08[NET] sending packet: from 69.69.69.83[500] to 2.6.3.4[500] (420 bytes)
Dec 29 11:02:23 charon: 08[IKE] received retransmit of request with ID 0, retransmitting response
Dec 29 11:02:23 charon: 08[IKE] <con18000|623>received retransmit of request with ID 0, retransmitting response
Dec 29 11:02:23 charon: 08[NET] received packet: from 2.6.3.4[500] to 69.69.69.83[500] (372 bytes)
</con18000|623>