I'm using ipsec-tools via pfSense (which just got 0.8b a few days ago).

When I upgraded I ran into a problem that you may be interested in.

At a site with two clients behind the same NAT box,
when one gets DPDed the other sa gets deleted 10 seconds later.



Feb 16 20:44:32 cujo racoon: [96.233.121.193] INFO: DPD: remote (ISAKMP-SA spi=1b1561a52a7ee073:72a9610bf3426989
) seems to be dead.
Feb 16 20:44:32 cujo racoon: INFO: purging ISAKMP-SA spi=1b1561a52a7ee073:72a9610bf3426989.
Feb 16 20:44:32 cujo racoon: INFO: generated policy, deleting it.
Feb 16 20:44:32 cujo racoon: INFO: purged IPsec-SA spi=2355238107.
Feb 16 20:44:32 cujo racoon: INFO: purged IPsec-SA spi=181612763.
Feb 16 20:44:32 cujo racoon: INFO: purged ISAKMP-SA spi=1b1561a52a7ee073:72a9610bf3426989.
Feb 16 20:44:33 cujo racoon: INFO: ISAKMP-SA deleted 216.177.7.226[4500]-96.233.121.193[4500] spi:1b1561a52a7ee0
73:72a9610bf3426989
Feb 16 20:44:42 cujo racoon: INFO: generated policy, deleting it.
Feb 16 20:44:42 cujo racoon: INFO: purged IPsec-SA proto_id=ESP spi=698705967.
Feb 16 20:44:42 cujo racoon: INFO: purging ISAKMP-SA spi=61974f5574b5226a:6b9d10203bcb3a5d.
Feb 16 20:44:42 cujo racoon: INFO: purged IPsec-SA spi=67173315.
Feb 16 20:44:42 cujo racoon: INFO: purged ISAKMP-SA spi=61974f5574b5226a:6b9d10203bcb3a5d.
Feb 16 20:44:43 cujo racoon: INFO: ISAKMP-SA deleted 216.177.7.226[4500]-96.233.121.193[28505] spi:61974f5574b5226a:6b9d10203bcb3a5d

I suspect these are related, though I don't understand the 9 second delay.

I'll include the session setup below in case it's helpful.

Let me know if you need something else, or if you think I'm just doing something stupid.

Brad

first client setup

Feb 16 20:03:30 cujo racoon: INFO: respond new phase 1 negotiation: 216.177.7.226[4500]<=>96.233.121.193[4500]
Feb 16 20:03:30 cujo racoon: INFO: begin Identity Protection mode.
Feb 16 20:03:30 cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00
Feb 16 20:03:30 cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-01
Feb 16 20:03:30 cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02 
Feb 16 20:03:30 cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-03
Feb 16 20:03:30 cujo racoon: INFO: received Vendor ID: RFC 3947
Feb 16 20:03:30 cujo racoon: INFO: received broken Microsoft ID: FRAGMENTATION
Feb 16 20:03:30 cujo racoon: INFO: received Vendor ID: DPD
Feb 16 20:03:30 cujo racoon: INFO: received Vendor ID: CISCO-UNITY
Feb 16 20:03:30 cujo racoon: [96.233.121.193] INFO: Selected NAT-T version: RFC 3947
Feb 16 20:03:30 cujo racoon: [96.233.121.193] WARNING: CR received, ignore it. It should be in other exchange.
Feb 16 20:03:30 cujo racoon: [216.177.7.226] INFO: Hashing 216.177.7.226[4500] with algo #2 
Feb 16 20:03:30 cujo racoon: INFO: NAT-D payload #0 verified
Feb 16 20:03:30 cujo racoon: [96.233.121.193] INFO: Hashing 96.233.121.193[4500] with algo #2 
Feb 16 20:03:30 cujo racoon: INFO: NAT-D payload #1 doesn't match
Feb 16 20:03:30 cujo racoon: INFO: NAT detected: PEER
Feb 16 20:03:30 cujo racoon: [96.233.121.193] INFO: Hashing 96.233.121.193[4500] with algo #2 
Feb 16 20:03:30 cujo racoon: [216.177.7.226] INFO: Hashing 216.177.7.226[4500] with algo #2 
Feb 16 20:03:30 cujo racoon: INFO: Adding remote and local NAT-D payloads.
Feb 16 20:03:30 cujo racoon: INFO: renegotiating phase1 to 96.233.121.193 due to active phase2
Feb 16 20:03:30 cujo racoon: INFO: ISAKMP-SA established 216.177.7.226[4500]-96.233.121.193[4500] spi:1b1561a52a7ee073:72a9610bf3426989

second client setup

Feb 16 20:16:34 cujo racoon: INFO: respond new phase 1 negotiation: 216.177.7.226[4500]<=>96.233.121.193[28505]
Feb 16 20:16:34 cujo racoon: INFO: begin Identity Protection mode.
Feb 16 20:16:34 cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00
Feb 16 20:16:34 cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-01
Feb 16 20:16:34 cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02 
Feb 16 20:16:34 cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-03
Feb 16 20:16:34 cujo racoon: INFO: received Vendor ID: RFC 3947
Feb 16 20:16:34 cujo racoon: INFO: received broken Microsoft ID: FRAGMENTATION
Feb 16 20:16:34 cujo racoon: INFO: received Vendor ID: DPD
Feb 16 20:16:34 cujo racoon: INFO: received Vendor ID: CISCO-UNITY
Feb 16 20:16:34 cujo racoon: [96.233.121.193] INFO: Selected NAT-T version: RFC 3947
Feb 16 20:16:34 cujo racoon: [96.233.121.193] WARNING: CR received, ignore it. It should be in other exchange.
Feb 16 20:16:34 cujo racoon: [216.177.7.226] INFO: Hashing 216.177.7.226[4500] with algo #2 
Feb 16 20:16:34 cujo racoon: INFO: NAT-D payload #0 verified
Feb 16 20:16:34 cujo racoon: [96.233.121.193] INFO: Hashing 96.233.121.193[28505] with algo #2 
Feb 16 20:16:34 cujo racoon: INFO: NAT-D payload #1 doesn't match
Feb 16 20:16:34 cujo racoon: INFO: NAT detected: PEER
Feb 16 20:16:34 cujo racoon: [96.233.121.193] INFO: Hashing 96.233.121.193[28505] with algo #2 
Feb 16 20:16:34 cujo racoon: [216.177.7.226] INFO: Hashing 216.177.7.226[4500] with algo #2 
Feb 16 20:16:34 cujo racoon: INFO: Adding remote and local NAT-D payloads.
Feb 16 20:16:34 cujo racoon: INFO: respond new phase 2 negotiation: 216.177.7.226[4500]<=>96.233.121.193[28505]
Feb 16 20:16:34 cujo racoon: INFO: Update the generated policy : 192.168.4.207/32[0] 192.168.3.0/24[0] proto=any dir=in
Feb 16 20:16:34 cujo racoon: INFO: Adjusting my encmode UDP-Tunnel->Tunnel
Feb 16 20:16:34 cujo racoon: INFO: Adjusting peer's encmode UDP-Tunnel(3)->Tunnel(1)
Feb 16 20:16:34 cujo racoon: WARNING: low key length proposed, mine:256 peer:128.
Feb 16 20:16:34 cujo racoon: WARNING: low key length proposed, mine:192 peer:128.
Feb 16 20:16:34 cujo racoon: INFO: NAT detected: PEER
Feb 16 20:16:34 cujo racoon: [96.233.121.193] INFO: Hashing 96.233.121.193[28505] with algo #2 
Feb 16 20:16:34 cujo racoon: [216.177.7.226] INFO: Hashing 216.177.7.226[4500] with algo #2 
Feb 16 20:16:34 cujo racoon: INFO: Adding remote and local NAT-D payloads.
Feb 16 20:16:34 cujo racoon: INFO: respond new phase 2 negotiation: 216.177.7.226[4500]<=>96.233.121.193[28505]
Feb 16 20:16:34 cujo racoon: INFO: Update the generated policy : 192.168.4.207/32[0] 192.168.3.0/24[0] proto=any
 dir=in
Feb 16 20:16:34 cujo racoon: INFO: Adjusting my encmode UDP-Tunnel->Tunnel
Feb 16 20:16:34 cujo racoon: INFO: Adjusting peer's encmode UDP-Tunnel(3)->Tunnel(1)
Feb 16 20:16:34 cujo racoon: WARNING: low key length proposed, mine:256 peer:128.
Feb 16 20:16:34 cujo racoon: WARNING: low key length proposed, mine:192 peer:128.
Feb 16 20:16:34 cujo racoon: INFO: ISAKMP-SA established 216.177.7.226[4500]-96.233.121.193[28505] spi:61974f5574b5226a:6b9d10203bcb3a5d
Feb 16 20:16:34 cujo racoon: INFO: IPsec-SA established: ESP 216.177.7.226[500]->96.233.121.193[500] spi=67173315(0x400fbc3)
Feb 16 20:16:34 cujo racoon: INFO: IPsec-SA established: ESP 216.177.7.226[500]->96.233.121.193[500] spi=698705967(0x29a5682f)
Feb 16 20:16:34 cujo racoon: ERROR: such policy does not already exist: "192.168.4.207/32[0] 192.168.3.0/24[0] proto=any dir=in"
Feb 16 20:16:34 cujo racoon: ERROR: such policy does not already exist: "192.168.3.0/24[0] 192.168.4.207/32[0] proto=any dir=out"
Feb 16 20:16:34 cujo racoon: ERROR: pfkey DELETE received: ESP 216.177.7.226[500]->96.233.121.193[500] spi=3462404135(0xce601827)
Feb 16 20:16:34 cujo racoon: INFO: IPsec-SA expired: ESP/Tunnel 96.233.121.193[500]->216.177.7.226[500] spi=97451148(0x5cefc8c)



--
Brad Langhorst
Chief Technology Officer
CoopMetrics