IPsec fails to renegotiate after loss of a peer
-
I'm starting this thread to sort of consolidate the information available about IPSec tunnels that fail and won't reestablish until after racoon (or the router) is restarted.
This happens on 1.2.2 and 1.2.3 (and 2.0), and with ipsec-tools 0.7.1 and 0.7.2. This seems to happen regardless of the 'DPD' option for most people, and it happens when connecting to all manner of devices (Other pfSense boxes, Cisco VPN concentrators, SonicWALLs, Fireboxes, &c).
What appears to happen is that racoon sees the peer go away, and removes the ISAKMP-SA/Phase 1 information for the tunnel, leaving the Phase 2 info present. Once that happens, it never attempts to reestablish Phase 1.
Here is a debug log from racoon showing the DPD failure, shows the SAD entries are still present, and shows the orphaned Phase 2 entries as racoon is stopped:
.40 is the pfSense 1.2.3 box, .49 is a Cisco VPN concentrator.
2009-05-14 15:42:47: DEBUG: DPD R-U-There sent (0) 2009-05-14 15:42:47: DEBUG: rescheduling send_r_u (5). 2009-05-14 15:42:52: DEBUG: DPD monitoring.... 2009-05-14 15:42:52: INFO: DPD: remote (ISAKMP-SA spi=4e71454083f1bb01:cb7350a8a507655d) seems to be dead. 2009-05-14 15:42:52: DEBUG: purging ISAKMP-SA spi=4e71454083f1bb01:cb7350a8a507655d. 2009-05-14 15:42:52: DEBUG2: getph1byaddr: start 2009-05-14 15:42:52: DEBUG2: local: x.x.x.40[500] 2009-05-14 15:42:52: DEBUG2: remote: x.x.x.49[500] 2009-05-14 15:42:52: DEBUG2: no match 2009-05-14 15:42:52: DEBUG: call pfkey_send_dump 2009-05-14 15:42:52: DEBUG: pk_recv: retry[0] recv() 2009-05-14 15:42:52: DEBUG: pk_recv: retry[0] recv() 2009-05-14 15:42:52: DEBUG: purged ISAKMP-SA spi=4e71454083f1bb01:cb7350a8a507655d. 2009-05-14 15:42:53: INFO: ISAKMP-SA deleted x.x.x.40[500]-x.x.x.49[500] spi:4e71454083f1bb01:cb7350a8a507655d 2009-05-14 15:42:53: DEBUG: IV freed 2009-05-14 15:44:37: DEBUG: msg 1 not interesting 2009-05-14 15:57:40: DEBUG: msg 1 not interesting 2009-05-14 16:01:54: DEBUG: msg 1 not interesting (In another terminal) # setkey -D x.x.x.40 x.x.x.49 esp mode=any spi=1523277686(0x5acb5f76) reqid=16399(0x0000400f) E: 3des-cbc 1b07ff4e 1ee98430 affd28f5 95acadb2 b5aed137 acb9e956 A: hmac-sha1 72f4ee83 ed2e3bc4 0dd28778 317afdbf 780a4074 seq=0x0000000d replay=4 flags=0x00000000 state=mature created: May 14 15:41:27 2009 current: May 14 15:45:39 2009 diff: 252(s) hard: 86400(s) soft: 69120(s) last: May 14 15:43:06 2009 hard: 0(s) soft: 0(s) current: 1768(bytes) hard: 0(bytes) soft: 0(bytes) allocated: 13 hard: 0 soft: 0 sadb_seq=1 pid=25748 refcnt=2 x.x.x.49 x.x.x.40 esp mode=tunnel spi=124083230(0x07655c1e) reqid=16400(0x00004010) E: 3des-cbc cd212cc9 ca1da6a2 e3190c8d 35d32612 e6a34822 c57f0258 A: hmac-sha1 c8e57b53 2a12b167 10ecf94f 278ff656 6c92872c seq=0x00000005 replay=4 flags=0x00000000 state=mature created: May 14 15:41:27 2009 current: May 14 15:45:39 2009 diff: 252(s) hard: 86400(s) soft: 69120(s) last: May 14 15:41:37 2009 hard: 0(s) soft: 0(s) current: 520(bytes) hard: 0(bytes) soft: 0(bytes) allocated: 5 hard: 0 soft: 0 sadb_seq=0 pid=25748 refcnt=1 (Back to the log) 2009-05-14 16:10:48: INFO: caught signal 2 2009-05-14 16:10:48: DEBUG: pk_recv: retry[0] recv() 2009-05-14 16:10:48: DEBUG: get pfkey FLUSH message 2009-05-14 16:10:48: DEBUG2: 02090000 02000000 00000000 f9600000 2009-05-14 16:10:48: DEBUG2: flushing all ph2 handlers... 2009-05-14 16:10:48: DEBUG2: got a ph2 handler to flush... 2009-05-14 16:10:48: DEBUG2: getph1byaddr: start 2009-05-14 16:10:48: DEBUG2: local: x.x.x.40[500] 2009-05-14 16:10:48: DEBUG2: remote: x.x.x.49[500] 2009-05-14 16:10:48: DEBUG2: no match 2009-05-14 16:10:48: DEBUG2: No ph1 handler found, could not send DELETE_SA 2009-05-14 16:10:48: DEBUG: an undead schedule has been deleted. 2009-05-14 16:10:48: DEBUG: IV freed 2009-05-14 16:10:49: DEBUG: call pfkey_send_dump 2009-05-14 16:10:49: DEBUG: pk_recv: retry[0] recv() 2009-05-14 16:10:49: INFO: racoon shutdownAlso noteworthy is that a tcpdump of a session in the "failed" state where pfSense believes it is still active does show that the remote side is sending an "invalid SPI" reply any time traffic attempts to traverse the tunnel. It seems like this invalid SPI message is either ignored by, or not seen by, racoon.
I have heard that there is discussion of a possible fix on the ipsec-tools-devel list, but nothing concrete yet.
If you have more information or similar experiences to share, feel free to post them.
Here are some related forum threads (I'm sure there are more):
http://forum.pfsense.org/index.php/topic,15703.0.html
http://forum.pfsense.org/index.php/topic,15678.0.html
http://forum.pfsense.org/index.php/topic,10371.0.html
http://forum.pfsense.org/index.php/topic,11851.0.html
http://forum.pfsense.org/index.php/topic,15638.0.html
http://forum.pfsense.org/index.php/topic,16086.0.html -
I have seen something similar with one of my VPN tunnels. It worked for two months with no problem. The other end rebooted and so did I and now we can't connect. I get phase 1 time issues with this one brand of firewall. I can't remember what the brand is.
It's a pain since I help then with their XenServer.
RC -
I have seen something similar with one of my VPN tunnels. It worked for two months with no problem. The other end rebooted and so did I and now we can't connect. I get phase 1 time issues with this one brand of firewall. I can't remember what the brand is.
That may be a different problem. The problem I am seeing clears up after the pfSense side that did not drop is either restarted or racoon is restarted.
-
I'm not sure if the issues I've been having fit with this issue. Mine will come back up eventually but it's hard to tell when. Maybe 2 minutes, maybe 8 hours later. I cannot restart the one which is at the remote location so I have to just wait for it to re-establish connection with my main router. They are both PFSense 1.2.2.
It's kinda funny that just when I read this thread I went to check the last time that connectivity went down and it was down right at that moment for about 2 minutes to this specific site.
-
It seems SAD entries you have (setkey -D) after the tunnel fails are different from those that were used when this tunnel was established (your log), no? I see different spi's.
I suspect the tunnel goes up again as soon as you setkey -F ? -
It seems SAD entries you have (setkey -D) after the tunnel fails are different from those that were used when this tunnel was established (your log), no? I see different spi's.
I suspect the tunnel goes up again as soon as you setkey -F ?The SPIs shown in the SAD entries are different than the SPI shown for the ISAKMP-SA which racoon deletes. They're not the same thing, as you can see from the log when it connects:
May 20 12:53:15 pfsense-123test racoon: INFO: IPsec-SA request for x.x.x.49 queued due to no phase1 found. May 20 12:53:15 pfsense-123test racoon: INFO: initiate new phase 1 negotiation: x.x.x.40[500]<=>x.x.x.49[500] May 20 12:53:15 pfsense-123test racoon: INFO: begin Aggressive mode. May 20 12:53:16 pfsense-123test racoon: INFO: received Vendor ID: CISCO-UNITY May 20 12:53:16 pfsense-123test racoon: INFO: received Vendor ID: draft-ietf-ipsra-isakmp-xauth-06.txt May 20 12:53:16 pfsense-123test racoon: INFO: received Vendor ID: DPD May 20 12:53:16 pfsense-123test racoon: NOTIFY: couldn't find the proper pskey, try to get one by the peer's address. May 20 12:53:16 pfsense-123test racoon: INFO: ISAKMP-SA established x.x.x.40[500]-x.x.x.49[500] spi:1a985545ad4bdc71:345805a19d6bbb0e May 20 12:53:16 pfsense-123test racoon: INFO: initiate new phase 2 negotiation: x.x.x.40[500]<=>x.x.x.49[500] May 20 12:53:16 pfsense-123test racoon: ERROR: unknown Informational exchange received. May 20 12:53:16 pfsense-123test racoon: ERROR: unknown Informational exchange received. May 20 12:53:16 pfsense-123test racoon: WARNING: ignore RESPONDER-LIFETIME notification. May 20 12:53:16 pfsense-123test racoon: INFO: IPsec-SA established: ESP x.x.x.49[0]->x.x.x.40[0] spi=208784171(0xc71cb2b) May 20 12:53:16 pfsense-123test racoon: INFO: IPsec-SA established: ESP x.x.x.40[500]->x.x.x.49[500] spi=28110911(0x1acf03f)Note that the ISAKMP-SA has one set of SPIs, and the IPSec-SA has another, different set, which if I check setkey right now, does match up:
pfsense-123test# setkey -D x.x.x.40 x.x.x.49 esp mode=any spi=28110911(0x01acf03f) reqid=16389(0x00004005) E: 3des-cbc dc09605c 0317db13 830e984a 533e9c2c edfbf6dc 8695f896 A: hmac-sha1 dddfdfef 52667b41 2174ebb4 217ae230 d458a5a7 seq=0x00000026 replay=4 flags=0x00000000 state=mature created: May 20 12:53:16 2009 current: May 20 12:56:21 2009 diff: 185(s) hard: 86400(s) soft: 69120(s) last: May 20 12:54:51 2009 hard: 0(s) soft: 0(s) current: 5168(bytes) hard: 0(bytes) soft: 0(bytes) allocated: 38 hard: 0 soft: 0 sadb_seq=1 pid=14572 refcnt=2 x.x.x.49 x.x.x.40 esp mode=tunnel spi=208784171(0x0c71cb2b) reqid=16390(0x00004006) E: 3des-cbc 2c130655 2b2d2a16 0333993b dff3264d f7251968 f2c3565b A: hmac-sha1 34236785 b00b9344 19b671bd a5d710f9 ff1222f6 seq=0x00000026 replay=4 flags=0x00000000 state=mature created: May 20 12:53:16 2009 current: May 20 12:56:21 2009 diff: 185(s) hard: 86400(s) soft: 69120(s) last: May 20 12:54:51 2009 hard: 0(s) soft: 0(s) current: 3952(bytes) hard: 0(bytes) soft: 0(bytes) allocated: 38 hard: 0 soft: 0 sadb_seq=0 pid=14572 refcnt=1 -
I suspect the tunnel goes up again as soon as you setkey -F ?
That does bring the tunnel back up, but it's still a manual process for something that should be happening automatically… It's easier than restarting things though.
-
This is the version I am running on my Alix Box.
1.2.2
built on Thu Jan 8 23:09:11 EST 2009 -
Great news everybody, it looks like this has been fixed in the development version of ipsec-tools!
I just got ipsec-tools 0.8-alpha20090525+natt to work on my 2.0 test box and things are working as they should.
Previously, DPD was removing the ISAKMP-SA, but not the IPsec-SA that went along with it. Now it appears to be clearing them all out.
Now this is what I'm seeing:
The connection establishes:
2009-05-28 12:51:17: INFO: respond new phase 1 negotiation: x.x.x.41[500]<=>x.x.x.40[500] 2009-05-28 12:51:17: INFO: begin Aggressive mode. 2009-05-28 12:51:17: INFO: received broken Microsoft ID: FRAGMENTATION 2009-05-28 12:51:17: INFO: received Vendor ID: DPD 2009-05-28 12:51:17: NOTIFY: couldn't find the proper pskey, try to get one by the peer's address. 2009-05-28 12:51:17: INFO: ISAKMP-SA established x.x.x.41[500]-x.x.x.40[500] spi:d75d671612ae7e75:07456176d8b6652c 2009-05-28 12:51:17: INFO: received INITIAL-CONTACT 2009-05-28 12:51:18: INFO: respond new phase 2 negotiation: x.x.x.41[500]<=>x.x.x.40[500] 2009-05-28 12:51:18: INFO: IPsec-SA established: ESP x.x.x.41[500]->x.x.x.40[500] spi=118325718(0x70d81d6) 2009-05-28 12:51:18: INFO: IPsec-SA established: ESP x.x.x.41[500]->x.x.x.40[500] spi=224293038(0xd5e70ae)And then when I unplug the cable:
2009-05-28 12:52:22: INFO: DPD: remote (ISAKMP-SA spi=d75d671612ae7e75:07456176d8b6652c) seems to be dead. 2009-05-28 12:52:22: INFO: purging ISAKMP-SA spi=d75d671612ae7e75:07456176d8b6652c. 2009-05-28 12:52:22: INFO: purged IPsec-SA spi=224293038. 2009-05-28 12:52:22: INFO: purged IPsec-SA spi=118325718. 2009-05-28 12:52:22: INFO: purged ISAKMP-SA spi=d75d671612ae7e75:07456176d8b6652c. 2009-05-28 12:52:23: INFO: ISAKMP-SA deleted x.x.x.41[500]-x.x.x.40[500] spi:d75d671612ae7e75:07456176d8b6652cAnd at that point, setkey -D shows nothing in the SA database, which is miles ahead of what I saw previously.
Since I compiled it on an 8-CURRENT box I can't get that same set of ipsec-tools binaries to run on a 1.2.3-RC system. Once I get that going I can confirm it works on my other test cases. I'll have to hunt down another box to (ab)use for more testing, but this looks very promising.
-
Great news jimp! Thanks for continuing to work on this.
-
Awesome! Hopefully this fix can make it into the 1.2.3 release…
-
The test version of ipsec-tools should be making its way into the snapshots fairly soon.
I'll try to post again once I'm sure it's working in a snapshot so that others can try, too.
-
The new ipsec-tools is in the snapshot for 1.2.3-RC1 on FreeBSD 7.2 that can be found here:
http://snapshots.pfsense.org/FreeBSD_RELENG_7_2/pfSense_RELENG_1_2/updates/
So far with the testing I have been able to perform it reestablishes dropped tunnels perfectly with DPD.
I have tested this Full Update:
http://snapshots.pfsense.org/FreeBSD_RELENG_7_2/pfSense_RELENG_1_2/updates/pfSense-Full-Update-1.2.3-20090528-2046.tgzAnd this ISO:
http://snapshots.pfsense.org/FreeBSD_RELENG_7_2/pfSense_RELENG_1_2/livecd_installer/pfSense-1.2.3-20090528-2038.iso.gzAnd the proper ipsec-tools is in both, and appears to work.
It should be working its way into the 1.2.3-RC1 based on FreeBSD 7.1 overnight as well.
I would appreciate as much testing as anyone can give this. I know this particular bug is fixed but with any change like this there is the potential to break other things. Please test and report back any issues (Especially people who can test NAT-T). Don't be afraid to report apocalyptic failures or anything else that happens.
-
Whoooooooooo so glad this has been looked at. Serious problems this cause me. Just need the traffic shaper fix now.
-
Jimp,
Some new for you, if the partner vpn starts a ping the tunnel reconnects. But it if drops from my end it will not estiablish. Thought I let you know. I try t get some information on the typ of firewall they are using.
RC -
Jimp,
Some new for you, if the partner vpn starts a ping the tunnel reconnects. But it if drops from my end it will not estiablish. Thought I let you know. I try t get some information on the typ of firewall they are using.
RCAt the moment we're in a holding pattern waiting on ipsec-tools 0.8 to get some fixes in, and I believe that's the way things are going to go.
There are too many of these issues to fix in ipsec-tools 0.7.2 with patches, unfortunately.
-
That's cool. I not updating at the momment. I more concerned with a stable enviroment. I can't afford any more down time.
I am in the process of moving and have a ton of stuff going on.
RC
-
At the moment we're in a holding pattern waiting on ipsec-tools 0.8 to get some fixes in, and I believe that's the way things are going to go.
There are too many of these issues to fix in ipsec-tools 0.7.2 with patches, unfortunately.
Now ipsec-tools 0.7.3 is out any thoughts on using it?
-
It was even worse off than 0.8 in some respects. We had to stay at 0.7.2 but drop NAT-T to get some semblance of stability.
-
Is IPsec renegotiating properly now in 1.2.3-RC3?
