IPsec fails to renegotiate after loss of a peer

jimp · May 29, 2009, 3:59 AM

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 shutdown

Also 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

fastcon68 · May 19, 2009, 3:47 AM

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

jimp · May 19, 2009, 3:50 AM

@fastcon68:

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.

focalguy · May 19, 2009, 4:27 PM

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.

Eugene · May 20, 2009, 2:38 AM

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 ?

jimp · May 20, 2009, 4:56 PM

@Eugene:

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

jimp · May 20, 2009, 5:06 PM

@Eugene:

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.

kapara · May 22, 2009, 12:18 AM

This is the version I am running on my Alix Box.

1.2.2
built on Thu Jan 8 23:09:11 EST 2009

jimp · May 28, 2009, 7:22 PM

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:07456176d8b6652c

And 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.

focalguy · May 28, 2009, 7:36 PM

Great news jimp! Thanks for continuing to work on this.

drees · May 28, 2009, 8:21 PM

Awesome! Hopefully this fix can make it into the 1.2.3 release…

jimp · May 28, 2009, 11:36 PM

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.

jimp · May 29, 2009, 3:58 AM

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.tgz

And this ISO:
http://snapshots.pfsense.org/FreeBSD_RELENG_7_2/pfSense_RELENG_1_2/livecd_installer/pfSense-1.2.3-20090528-2038.iso.gz

And 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.

Jonb · Jun 29, 2009, 8:19 AM

Whoooooooooo so glad this has been looked at. Serious problems this cause me. Just need the traffic shaper fix now.

fastcon68 · Jul 6, 2009, 10:31 PM

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 · Jul 6, 2009, 10:33 PM

@fastcon68:

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

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.

fastcon68 · Jul 6, 2009, 10:54 PM

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

Rockets · Sep 23, 2009, 12:34 PM

@jimp:

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?

jimp · Sep 23, 2009, 12:38 PM

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.

Rockets · Sep 23, 2009, 12:57 PM

Is IPsec renegotiating properly now in 1.2.3-RC3?