Re: status of rightprotoport=17/%any with xlt2pd, XP and Mac OS X?

On Thu, 12 Apr 2007, Clifford T. Matthews wrote:

> This one doesn't:

This is completely different from the bug I was
expecting...

Mcr: note that this is another issue of:

> Apr 12 13:58:29 first pluto[4245]: | refine_connection:
picking new best sbnyc-l2tpX509-int (wild=15,
peer_pathlen=0/our=0)
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[1] 192.168.10.29 #1: switched
from "sbnyc-l2tpX509-int" to
"sbnyc-l2tpX509-int"

where a conn switches into itself. Full logs about the two
conns confusing each other, and the remote hanging
up on us follows below.

> Apr 12 13:58:17 first pluto[4245]: Starting Pluto
(Openswan Version 2.4.7 PLUTO_SENDS_VENDORID
PLUTO_USES_KEYRR; Vendor ID OEZ~BaB]r134p_)

> Apr 12 13:58:29 first pluto[4245]: packet from
192.168.10.29:500: ignoring Vendor ID payload [MS NT5
ISAKMPOAKLEY 00000004]
> Apr 12 13:58:29 first pluto[4245]: packet from
192.168.10.29:500: ignoring Vendor ID payload
[FRAGMENTATION]
> Apr 12 13:58:29 first pluto[4245]: packet from
192.168.10.29:500: received Vendor ID payload
[draft-ietf-ipsec-nat-t-ike-02_n] method set to=106
> Apr 12 13:58:29 first pluto[4245]: packet from
192.168.10.29:500: ignoring Vendor ID payload
[Vid-Initial-Contact]
> Apr 12 13:58:29 first pluto[4245]: |
find_host_connection called from main_inI1_outR1
> Apr 12 13:58:29 first pluto[4245]: | find_host_pair:
comparing to 192.168.10.1:500 0.0.0.0:500
> Apr 12 13:58:29 first pluto[4245]: | find_host_pair:
comparing to 216.254.70.239:500 0.0.0.0:500
> Apr 12 13:58:29 first pluto[4245]: |
find_host_pair_conn (find_host_connection2):
192.168.10.1:500 192.168.10.29:500 -> hp:none
> Apr 12 13:58:29 first pluto[4245]: |
find_host_connection called from main_inI1_outR1
> Apr 12 13:58:29 first pluto[4245]: | find_host_pair:
comparing to 192.168.10.1:500 0.0.0.0:500
> Apr 12 13:58:29 first pluto[4245]: |
find_host_pair_conn (find_host_connection2):
192.168.10.1:500 %any:500 -> hp:sbnyc-l2tpX509-int
> Apr 12 13:58:29 first pluto[4245]: | find_host_pair:
comparing to 192.168.10.1:500 0.0.0.0:500
> Apr 12 13:58:29 first pluto[4245]: | find_host_pair:
comparing to 216.254.70.239:500 0.0.0.0:500
> Apr 12 13:58:29 first pluto[4245]: |
connect_to_host_pair: 192.168.10.1:500 192.168.10.29:500
-> hp:none
> Apr 12 13:58:29 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[1] 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[1] 192.168.10.29 #1:
responding to Main Mode from unknown peer 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]: | sender checking
NAT-t: 1 and 106
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[1] 192.168.10.29 #1:
transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[1] 192.168.10.29 #1:
STATE_MAIN_R1: sent MR1, expecting MI2
> Apr 12 13:58:29 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[1] 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]: | inI2: checking
NAT-t: 1 and 4
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[1] 192.168.10.29 #1:
NAT-Traversal: Result using
draft-ietf-ipsec-nat-t-ike-02/03: no NAT detected
> Apr 12 13:58:29 first pluto[4245]: | main inI2_outR2:
calculated ke+nonce, sending R2
> Apr 12 13:58:29 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[1] 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]: |
find_host_connection called from collect_rw_ca_candidates
> Apr 12 13:58:29 first pluto[4245]: | find_host_pair:
comparing to 192.168.10.1:500 192.168.10.29:500
> Apr 12 13:58:29 first pluto[4245]: | find_host_pair:
comparing to 192.168.10.1:500 0.0.0.0:500
> Apr 12 13:58:29 first pluto[4245]: |
find_host_pair_conn (find_host_connection2):
192.168.10.1:500 %any:500 -> hp:sbnyc-l2tpX509-int
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[1] 192.168.10.29 #1:
transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[1] 192.168.10.29 #1:
STATE_MAIN_R2: sent MR2, expecting MI3
> Apr 12 13:58:29 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[1] 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[1] 192.168.10.29 #1: Main
mode peer ID is ID_DER_ASN1_DN: 'C=US, O=stolenbases.com,
OU=first, CN=ctm, E=ctmstolenbases.com'
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[1] 192.168.10.29 #1: no crl
from issuer "C=US, O=stolenbases.com, OU=first,
CN=CA" found (strict=no)
> Apr 12 13:58:29 first pluto[4245]: | refine_connection:
starting with sbnyc-l2tpX509-int
> Apr 12 13:58:29 first pluto[4245]: |    match_id
a=C=US, O=stolenbases.com, OU=first, CN=ctm, E=ctmstolenbases.com
> Apr 12 13:58:29 first pluto[4245]: |            
b=192.168.10.29
> Apr 12 13:58:29 first pluto[4245]: |    results  fail
> Apr 12 13:58:29 first pluto[4245]: |   trusted_ca
called with a=C=US, O=stolenbases.com, OU=first, CN=CA
b=C=US, O=stolenbases.com, OU=first, CN=CA
> Apr 12 13:58:29 first pluto[4245]: |   trusted_ca
called with a=C=US, O=stolenbases.com, OU=first, CN=CA
b=C=US, O=stolenbases.com, OU=first, CN=CA
> Apr 12 13:58:29 first pluto[4245]: | refine_connection:
checking sbnyc-l2tpX509-int against sbnyc-l2tpX509-int,
best=(none) with match=0(id=0/ca=1/reqca=1)
> Apr 12 13:58:29 first pluto[4245]: | find_host_pair:
comparing to 192.168.10.1:500 0.0.0.0:500
> Apr 12 13:58:29 first pluto[4245]: |
find_host_pair_conn (refine_host_connection):
192.168.10.1:500 %any:500 -> hp:sbnyc-l2tpX509-int
> Apr 12 13:58:29 first pluto[4245]: |    match_id
a=C=US, O=stolenbases.com, OU=first, CN=ctm, E=ctmstolenbases.com
> Apr 12 13:58:29 first pluto[4245]: |            
b=(none)
> Apr 12 13:58:29 first pluto[4245]: |    results 
matched
> Apr 12 13:58:29 first pluto[4245]: |   trusted_ca
called with a=C=US, O=stolenbases.com, OU=first, CN=CA
b=C=US, O=stolenbases.com, OU=first, CN=CA
> Apr 12 13:58:29 first pluto[4245]: |   trusted_ca
called with a=C=US, O=stolenbases.com, OU=first, CN=CA
b=C=US, O=stolenbases.com, OU=first, CN=CA
> Apr 12 13:58:29 first pluto[4245]: | refine_connection:
checking sbnyc-l2tpX509-int against sbnyc-l2tpX509-int,
best=(none) with match=1(id=1/ca=1/reqca=1)
> Apr 12 13:58:29 first pluto[4245]: | refine_connection:
checked sbnyc-l2tpX509-int against sbnyc-l2tpX509-int, now
for see if best
> Apr 12 13:58:29 first pluto[4245]: | refine_connection:
picking new best sbnyc-l2tpX509-int (wild=15,
peer_pathlen=0/our=0)
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[1] 192.168.10.29 #1: switched
from "sbnyc-l2tpX509-int" to
"sbnyc-l2tpX509-int"
> Apr 12 13:58:29 first pluto[4245]: |    match_id
a=C=US, O=stolenbases.com, OU=first, CN=ctm, E=ctmstolenbases.com
> Apr 12 13:58:29 first pluto[4245]: |            
b=(none)
> Apr 12 13:58:29 first pluto[4245]: |    results 
matched
> Apr 12 13:58:29 first pluto[4245]: | find_host_pair:
comparing to 192.168.10.1:500 0.0.0.0:500
> Apr 12 13:58:29 first pluto[4245]: | find_host_pair:
comparing to 192.168.10.1:500 192.168.10.29:500
> Apr 12 13:58:29 first pluto[4245]: |
connect_to_host_pair: 192.168.10.1:500 192.168.10.29:500
-> hp:sbnyc-l2tpX509-int
> Apr 12 13:58:29 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[2] 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[1] 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[2] 192.168.10.29 #1: deleting
connection "sbnyc-l2tpX509-int" instance with peer
192.168.10.29 {isakmp=#0/ipsec=#0}
> Apr 12 13:58:29 first pluto[4245]: |   trusted_ca
called with a=C=US, O=stolenbases.com, OU=first, CN=CA
b=C=US, O=stolenbases.com, OU=first, CN=CA
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[2] 192.168.10.29 #1: I am
sending my cert
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[2] 192.168.10.29 #1:
transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[2] 192.168.10.29 #1:
STATE_MAIN_R3: sent MR3, ISAKMP SA established
{auth=OAKLEY_RSA_SIG cipher=oakley_3des_cbc_192
prf=oakley_sha group=modp2048}
> Apr 12 13:58:29 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[2] 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]: |
find_client_connection starting with sbnyc-l2tpX509-int
> Apr 12 13:58:29 first pluto[4245]: |   looking for
192.168.10.1/32:17/1701 -> 192.168.10.29/32:17/1701
> Apr 12 13:58:29 first pluto[4245]: |   concrete
checking against sr#0 192.168.10.1/32 -> 0.0.0.0/32
> Apr 12 13:58:29 first pluto[4245]: |    match_id
a=C=US, O=stolenbases.com, OU=first, CN=ctm, E=ctmstolenbases.com
> Apr 12 13:58:29 first pluto[4245]: |            
b=C=US, O=stolenbases.com, OU=first, CN=ctm, E=ctmstolenbases.com
> Apr 12 13:58:29 first pluto[4245]: |    results 
matched
> Apr 12 13:58:29 first pluto[4245]: |   trusted_ca
called with a=C=US, O=stolenbases.com, OU=first, CN=CA
b=C=US, O=stolenbases.com, OU=first, CN=CA
> Apr 12 13:58:29 first pluto[4245]: |   fc_try trying
sbnyc-l2tpX509-int:192.168.10.1/32:17/1701 ->
192.168.10.29/32:17/0 vs
sbnyc-l2tpX509-int:192.168.10.1/32:17/1701 ->
0.0.0.0/32:17/0
> Apr 12 13:58:29 first pluto[4245]: |   fc_try
concluding with sbnyc-l2tpX509-int [128]
> Apr 12 13:58:29 first pluto[4245]: |   fc_try
sbnyc-l2tpX509-int gives sbnyc-l2tpX509-int
> Apr 12 13:58:29 first pluto[4245]: |   concluding with
d = sbnyc-l2tpX509-int
> Apr 12 13:58:29 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[2] 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]: | quick inI1_outR1:
calculated ke+nonce, sending R1
> Apr 12 13:58:29 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[2] 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[2] 192.168.10.29 #2:
responding to Quick Mode {msgid:dcbe9fe6}
> Apr 12 13:58:29 first pluto[4245]: | finished
processing quick inI1
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[2] 192.168.10.29 #2:
transition from state STATE_QUICK_R0 to state
STATE_QUICK_R1
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[2] 192.168.10.29 #2:
STATE_QUICK_R1: sent QR1, inbound IPsec SA installed,
expecting QI2
> Apr 12 13:58:29 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[2] 192.168.10.29
> Apr 12 13:58:29 first pluto[4245]: | route_and_eroute
with c: sbnyc-l2tpX509-int (next: none) ero:null esr:{(nil)}
ro:null rosr:{(nil)} and state: 2
> Apr 12 13:58:29 first pluto[4245]: |   trusted_ca
called with a=C=US, O=stolenbases.com, OU=first, CN=CA
b=C=US, O=stolenbases.com, OU=first, CN=CA
> Apr 12 13:58:29 first last message repeated 2 times
> Apr 12 13:58:29 first pluto[4245]: | inI2: instance
sbnyc-l2tpX509-int[2], setting newest_ipsec_sa to #2 (was
#0) (spd.eroute=#2)
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[2] 192.168.10.29 #2:
transition from state STATE_QUICK_R1 to state
STATE_QUICK_R2
> Apr 12 13:58:29 first pluto[4245]:
"sbnyc-l2tpX509-int"[2] 192.168.10.29 #2:
STATE_QUICK_R2: IPsec SA established {ESP=>0x277fff6e
<0x2a4299c4 xfrm=3DES_0-HMAC_MD5 NATD=none DPD=none}

So the connection comes up

> Apr 12 13:58:49 first pluto[4245]: | processing
connection sbnyc-l2tpX509-int[2] 192.168.10.29
> Apr 12 13:59:04 first last message repeated 3 times

But the other instance is still stuck somewhere

> Apr 12 13:59:04 first pluto[4245]:
"sbnyc-l2tpX509-int"[2] 192.168.10.29 #1: received
Delete SA(0x277fff6e) payload: deleting IPSEC State #2

And as a result, Windows seems to hang up on us.

Clifford, Could you also enable OAKLEY.LOG on the Windows
machine and get us that logs as well?

Paul
_______________________________________________
Usersopenswan.org
http
://lists.openswan.org/mailman/listinfo/users
Building and Integrating Virtual Private Networks with
Openswan: 
http://www.amazon.com/gp/product/1904811
256/104-3099591-2946327?n=283155

Re: status of rightprotoport=17/%any with xlt2pd, XP and Mac OS X?

Thread: Re: status of rightprotoport=17/%any with xlt2pd, XP and Mac OS X?