Thread: [Ipsec-tools-devel] possible bug in 0.8b re dpd
Brought to you by:
mit_warlord,
netbsd
From: Brad L. <br...@co...> - 2011-02-17 03:09:59
|
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 |