[Openswan Users] status of rightprotoport=17/%any with xlt2pd, XP and Mac OS X?
Paul Wouters
paul at xelerance.com
Thu Apr 12 18:42:57 EDT 2007
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]r\134p_)
> 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=ctm at stolenbases.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=ctm at stolenbases.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=ctm at stolenbases.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=ctm at stolenbases.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=ctm at stolenbases.com
> Apr 12 13:58:29 first pluto[4245]: | b=C=US, O=stolenbases.com, OU=first, CN=ctm, E=ctm at stolenbases.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
More information about the Users
mailing list