[prev in list] [next in list] [prev in thread] [next in thread]
List: ipsec-tools-devel
Subject: [Ipsec-tools-devel] possible bug in 0.8b re dpd
From: Brad Langhorst <brad () coopmetrics ! coop>
Date: 2011-02-17 2:45:52
Message-ID: AANLkTiknJj4pv=qNdU0nSwSLhBDfhXLY5VXcYKDBpvjT () mail ! gmail ! com
[Download RAW message or body]
[Attachment #2 (multipart/alternative)]
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
[Attachment #5 (text/html)]
I'm using ipsec-tools via pfSense (which just got 0.8b a few days \
ago).<div><div><br>When I upgraded I ran into a problem that you may be interested \
in.</div> <div><br></div><div><span style="font-family:verdana, \
sans-serif;line-height:16px">At a site with two clients behind the same NAT \
box,<br>when one gets DPDed the other sa gets deleted 10 seconds later.</span><br> \
<div><br></div><div><br></div><div><span style="font-family:verdana, \
sans-serif;line-height:16px">Feb 16 20:44:32 cujo racoon: [96.233.121.193] INFO: DPD: \
remote (ISAKMP-SA spi=1b1561a52a7ee073:72a9610bf3426989<br> ) seems to be \
dead.<br>Feb 16 20:44:32 cujo racoon: INFO: purging ISAKMP-SA \
spi=1b1561a52a7ee073:72a9610bf3426989.<br>Feb 16 20:44:32 cujo racoon: INFO: \
generated policy, deleting it.<br>Feb 16 20:44:32 cujo racoon: INFO: purged IPsec-SA \
spi=2355238107.<br>
Feb 16 20:44:32 cujo racoon: INFO: purged IPsec-SA spi=181612763.<br>Feb 16 20:44:32 \
cujo racoon: INFO: purged ISAKMP-SA spi=1b1561a52a7ee073:72a9610bf3426989.<br>Feb 16 \
20:44:33 cujo racoon: INFO: ISAKMP-SA deleted \
216.177.7.226[4500]-96.233.121.193[4500] spi:1b1561a52a7ee0<br>
73:72a9610bf3426989<br>Feb 16 20:44:42 cujo racoon: INFO: generated policy, deleting \
it.<br>Feb 16 20:44:42 cujo racoon: INFO: purged IPsec-SA proto_id=ESP \
spi=698705967.<br>Feb 16 20:44:42 cujo racoon: INFO: purging ISAKMP-SA \
spi=61974f5574b5226a:6b9d10203bcb3a5d.<br>
Feb 16 20:44:42 cujo racoon: INFO: purged IPsec-SA spi=67173315.<br>Feb 16 20:44:42 \
cujo racoon: INFO: purged ISAKMP-SA spi=61974f5574b5226a:6b9d10203bcb3a5d.<br>Feb 16 \
20:44:43 cujo racoon: INFO: ISAKMP-SA deleted \
216.177.7.226[4500]-96.233.121.193[28505] \
spi:61974f5574b5226a:6b9d10203bcb3a5d</span></div>
<div><br></div><div>I suspect these are related, though I don't understand the 9 \
second delay.</div><div><br></div><div>I'll include the session setup below in \
case it's helpful.</div><div><br></div><div>Let me know if you need something \
else, or if you think I'm just doing something stupid.</div> \
<div><br></div><div>Brad</div><div><br></div><div>first client setup</div><div><meta \
charset="utf-8"><div><br class="Apple-interchange-newline">Feb 16 20:03:30 cujo \
racoon: INFO: respond new phase 1 negotiation: \
216.177.7.226[4500]<=>96.233.121.193[4500]</div> <div>Feb 16 20:03:30 cujo \
racoon: INFO: begin Identity Protection mode.</div><div>Feb 16 20:03:30 cujo racoon: \
INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00</div><div>Feb 16 20:03:30 \
cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-01</div> <div>Feb \
16 20:03:30 cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02 \
</div><div>Feb 16 20:03:30 cujo racoon: INFO: received Vendor ID: \
draft-ietf-ipsec-nat-t-ike-03</div><div>Feb 16 20:03:30 cujo racoon: INFO: received \
Vendor ID: RFC 3947</div> <div>Feb 16 20:03:30 cujo racoon: INFO: received broken \
Microsoft ID: FRAGMENTATION</div><div>Feb 16 20:03:30 cujo racoon: INFO: received \
Vendor ID: DPD</div><div>Feb 16 20:03:30 cujo racoon: INFO: received Vendor ID: \
CISCO-UNITY</div> <div>Feb 16 20:03:30 cujo racoon: [96.233.121.193] INFO: Selected \
NAT-T version: RFC 3947</div><div>Feb 16 20:03:30 cujo racoon: [96.233.121.193] \
WARNING: CR received, ignore it. It should be in other \
exchange.</div><div>
Feb 16 20:03:30 cujo racoon: [216.177.7.226] INFO: Hashing 216.177.7.226[4500] with \
algo #2 </div><div>Feb 16 20:03:30 cujo racoon: INFO: NAT-D payload #0 \
verified</div><div>Feb 16 20:03:30 cujo racoon: [96.233.121.193] INFO: Hashing \
96.233.121.193[4500] with algo #2 </div> <div>Feb 16 20:03:30 cujo racoon: INFO: \
NAT-D payload #1 doesn't match</div><div>Feb 16 20:03:30 cujo racoon: INFO: NAT \
detected: PEER</div><div>Feb 16 20:03:30 cujo racoon: [96.233.121.193] INFO: Hashing \
96.233.121.193[4500] with algo #2 </div> <div>Feb 16 20:03:30 cujo racoon: \
[216.177.7.226] INFO: Hashing 216.177.7.226[4500] with algo #2 </div><div>Feb 16 \
20:03:30 cujo racoon: INFO: Adding remote and local NAT-D payloads.</div><div>Feb 16 \
20:03:30 cujo racoon: INFO: renegotiating phase1 to 96.233.121.193 due to active \
phase2</div> <div>Feb 16 20:03:30 cujo racoon: INFO: ISAKMP-SA established \
216.177.7.226[4500]-96.233.121.193[4500] \
spi:1b1561a52a7ee073:72a9610bf3426989</div></div><div><br></div><div>second client \
setup</div><div><br></div><div><div>
Feb 16 20:16:34 cujo racoon: INFO: respond new phase 1 negotiation: \
216.177.7.226[4500]<=>96.233.121.193[28505]</div><div>Feb 16 20:16:34 cujo \
racoon: INFO: begin Identity Protection mode.</div><div>Feb 16 20:16:34 cujo racoon: \
INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-00</div> <div>Feb 16 20:16:34 \
cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-01</div><div>Feb 16 \
20:16:34 cujo racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02 \
</div><div>Feb 16 20:16:34 cujo racoon: INFO: received Vendor ID: \
draft-ietf-ipsec-nat-t-ike-03</div> <div>Feb 16 20:16:34 cujo racoon: INFO: received \
Vendor ID: RFC 3947</div><div>Feb 16 20:16:34 cujo racoon: INFO: received broken \
Microsoft ID: FRAGMENTATION</div><div>Feb 16 20:16:34 cujo racoon: INFO: received \
Vendor ID: DPD</div> <div>Feb 16 20:16:34 cujo racoon: INFO: received Vendor ID: \
CISCO-UNITY</div><div>Feb 16 20:16:34 cujo racoon: [96.233.121.193] INFO: Selected \
NAT-T version: RFC 3947</div><div>Feb 16 20:16:34 cujo racoon: [96.233.121.193] \
WARNING: CR received, ignore it. It should be in other exchange.</div> <div>Feb 16 \
20:16:34 cujo racoon: [216.177.7.226] INFO: Hashing 216.177.7.226[4500] with algo #2 \
</div><div>Feb 16 20:16:34 cujo racoon: INFO: NAT-D payload #0 verified</div><div>Feb \
16 20:16:34 cujo racoon: [96.233.121.193] INFO: Hashing 96.233.121.193[28505] with \
algo #2 </div> <div>Feb 16 20:16:34 cujo racoon: INFO: NAT-D payload #1 doesn't \
match</div><div>Feb 16 20:16:34 cujo racoon: INFO: NAT detected: PEER</div><div>Feb \
16 20:16:34 cujo racoon: [96.233.121.193] INFO: Hashing 96.233.121.193[28505] with \
algo #2 </div> <div>Feb 16 20:16:34 cujo racoon: [216.177.7.226] INFO: Hashing \
216.177.7.226[4500] with algo #2 </div><div>Feb 16 20:16:34 cujo racoon: INFO: Adding \
remote and local NAT-D payloads.</div><div>Feb 16 20:16:34 cujo racoon: INFO: respond \
new phase 2 negotiation: 216.177.7.226[4500]<=>96.233.121.193[28505]</div> \
<div>Feb 16 20:16:34 cujo racoon: INFO: Update the generated policy : <a \
href="http://192.168.4.207/32[0]">192.168.4.207/32[0]</a> <a \
href="http://192.168.3.0/24[0]">192.168.3.0/24[0]</a> proto=any dir=in</div><div>Feb \
16 20:16:34 cujo racoon: INFO: Adjusting my encmode UDP-Tunnel->Tunnel</div> \
<div>Feb 16 20:16:34 cujo racoon: INFO: Adjusting peer's encmode \
UDP-Tunnel(3)->Tunnel(1)</div><div>Feb 16 20:16:34 cujo racoon: WARNING: low key \
length proposed, mine:256 peer:128.</div><div>Feb 16 20:16:34 cujo racoon: WARNING: \
low key length proposed, mine:192 peer:128.</div> <div>Feb 16 20:16:34 cujo racoon: \
INFO: NAT detected: PEER</div><div>Feb 16 20:16:34 cujo racoon: [96.233.121.193] \
INFO: Hashing 96.233.121.193[28505] with algo #2 </div><div>Feb 16 20:16:34 cujo \
racoon: [216.177.7.226] INFO: Hashing 216.177.7.226[4500] with algo #2 </div> \
<div>Feb 16 20:16:34 cujo racoon: INFO: Adding remote and local NAT-D \
payloads.</div><div>Feb 16 20:16:34 cujo racoon: INFO: respond new phase 2 \
negotiation: 216.177.7.226[4500]<=>96.233.121.193[28505]</div><div>Feb 16 \
20:16:34 cujo racoon: INFO: Update the generated policy : <a \
href="http://192.168.4.207/32[0]">192.168.4.207/32[0]</a> <a \
href="http://192.168.3.0/24[0]">192.168.3.0/24[0]</a> proto=any</div> <div> \
dir=in</div><div>Feb 16 20:16:34 cujo racoon: INFO: Adjusting my encmode \
UDP-Tunnel->Tunnel</div><div>Feb 16 20:16:34 cujo racoon: INFO: Adjusting \
peer's encmode UDP-Tunnel(3)->Tunnel(1)</div><div>Feb 16 20:16:34 cujo racoon: \
WARNING: low key length proposed, mine:256 peer:128.</div> <div>Feb 16 20:16:34 cujo \
racoon: WARNING: low key length proposed, mine:192 peer:128.</div><div>Feb 16 \
20:16:34 cujo racoon: INFO: ISAKMP-SA established \
216.177.7.226[4500]-96.233.121.193[28505] spi:61974f5574b5226a:6b9d10203bcb3a5d</div> \
<div>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)</div><div>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)</div> <div>Feb \
16 20:16:34 cujo racoon: ERROR: such policy does not already exist: "<a \
href="http://192.168.4.207/32[0]">192.168.4.207/32[0]</a> <a \
href="http://192.168.3.0/24[0]">192.168.3.0/24[0]</a> proto=any dir=in"</div> \
<div>Feb 16 20:16:34 cujo racoon: ERROR: such policy does not already exist: "<a \
href="http://192.168.3.0/24[0]">192.168.3.0/24[0]</a> <a \
href="http://192.168.4.207/32[0]">192.168.4.207/32[0]</a> proto=any \
dir=out"</div> <div>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)</div><div>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)</div> </div><div><br></div><div><br></div><div><br>-- \
<br>Brad Langhorst<br>Chief Technology Officer<br>CoopMetrics<br> </div></div></div>
------------------------------------------------------------------------------
The ultimate all-in-one performance toolkit: Intel(R) Parallel Studio XE:
Pinpoint memory and threading errors before they happen.
Find and fix more than 250 security defects in the development cycle.
Locate bottlenecks in serial and parallel code that limit performance.
http://p.sf.net/sfu/intel-dev2devfeb
_______________________________________________
Ipsec-tools-devel mailing list
Ipsec-tools-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/ipsec-tools-devel
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic