[Openswan Users] Error: "initial Main Mode message received on 192.168.23.23:500 but no connection has been authorized"
BUI18
lbui18 at yahoo.com
Tue Apr 8 14:00:44 EDT 2008
Hi Jacco -
Since there's NATing involved here. Could it be that I don't have the right NAT-T patch? We installed Openswan using apt-get from Ubuntu. And we see the following when we start Openswan:
Apr 8 10:22:30 localhost pluto[29484]: Setting NAT-Traversal port-4500 floating to on
Apr 8 10:22:30 localhost pluto[29484]: port floating activation criteria nat_t=1/port_fload=1
Apr 8 10:22:30 localhost pluto[29484]: including NAT-Traversal patch (Version 0.6c)
I am assuming here that it is installed.
Anyway...it looks like it gets to phase 1 but no further:
000 "DIR130-JON": 192.168.23.0/24===192.168.23.23---192.168.23.1...66.27.f.g===192.168.99.0/24; prospective erouted; eroute owner: #0
000 "DIR130-JON": srcip=unset; dstip=unset; srcup=ipsec _updown; dstup=ipsec _updown;
000 "DIR130-JON": ike_life: 28800s; ipsec_life: 3600s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0
000 "DIR130-JON": policy: PSK+ENCRYPT+TUNNEL+PFS+UP; prio: 24,24; interface: eth0;
000 "DIR130-JON": newest ISAKMP SA: #3; newest IPsec SA: #0;
000 "DIR130-JON": IKE algorithm newest: 3DES_CBC_192-MD5-MODP1024
000
000 #1: "DIR130-JON":500 STATE_MAIN_I1 (sent MI1, expecting MR1); EVENT_RETRANSMIT in 11s; nodpd
000 #1: pending Phase 2 for "DIR130-JON" replacing #0
000 #3: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 28481s; newest ISAKMP; lastdpd=-1s(seq in:0 out:0)
000 #2: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 28410s; lastdpd=-1s(seq in:0 out:0)
Also....from auth.log I can see that it does try to get to phase 2...eventually...but never completes.
It starts like this for a while and repeats:
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: responding to Main Mode
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: STATE_MAIN_R1: sent MR1, expecting MI2
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: NAT-Traversal: Result using 3: i am NATed
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: STATE_MAIN_R2: sent MR2, expecting MI3
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: Main mode peer ID is ID_IPV4_ADDR: '66.27.113.46'
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: I did not send a certificate because I do not have one.
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_md5 group=modp1024}
Apr 8 10:27:31 localhost pluto[29484]: "DIR130-JON" #6: Informational Exchange message must be encrypted
Apr 8 10:27:41 localhost pluto[29484]: "DIR130-JON" #6: retransmitting in response to duplicate packet; already STATE_MAIN_R3
Apr 8 10:27:41 localhost pluto[29484]: "DIR130-JON" #6: Informational Exchange message must be encrypted
Apr 8 10:28:01 localhost pluto[29484]: "DIR130-JON" #6: retransmitting in response to duplicate packet; already STATE_MAIN_R3
Apr 8 10:28:01 localhost pluto[29484]: "DIR130-JON" #6: Informational Exchange message must be encrypted
Apr 8 10:28:41 localhost pluto[29484]: packet from 66.27.f.g:4500: received Vendor ID payload [RFC 3947] method set to=109
Apr 8 10:28:41 localhost pluto[29484]: packet from 66.27.f.g:4500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using method 109
Apr 8 10:28:41 localhost pluto[29484]: packet from 66.27.f.g:4500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but already using method 109
Apr 8 10:28:41 localhost pluto[29484]: packet from 66.27.f.g:4500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
Apr 8 10:28:41 localhost pluto[29484]: packet from 66.27.f.g:4500: received Vendor ID payload [Dead Peer Detection]
Not sure why it getting the encryption errors regarding STATE_MAIN_R3
Tcpdump shows the following while the above in auth.log is going on:
10:29:40.500815 IP 192.168.23.23.500 > 66.27.f.g.500: isakmp: phase 1 I ident
10:29:49.502544 IP 192.168.23.23.4500 > 66.27.f.g.4500: isakmp-nat-keep-alive
10:29:51.524623 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I ident
10:29:51.525060 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 1 R ident
10:29:51.591027 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I ident
10:29:51.597227 IP 192.168.23.23.4500 > 66.27.113.46.4500: NONESP-encap: isakmp: phase 1 R ident
10:29:51.654476 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I ident[E]
10:29:51.654783 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 1 R ident[E]
10:29:51.677106 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I inf
10:30:01.671285 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I ident[E]
10:30:01.671462 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 1 R ident[E]
10:30:01.697723 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I inf
10:30:09.702301 IP 192.168.23.23.4500 > 66.27.f.g.4500: isakmp-nat-keep-alive
10:30:20.705970 IP 192.168.23.23.500 > 66.27.f.g.500: isakmp: phase 1 I ident
10:30:21.724434 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I ident[E]
10:30:21.724613 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 1 R ident[E]
10:30:21.747428 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I inf
10:30:29.748732 IP 192.168.23.23.4500 > 66.27.f.g.4500: isakmp-nat-keep-alive
Not sure what this means in tcpdump.
Meanwhile "ipsec auto status" has grown and will keep growing. What is it trying to do here..I have no idea:
000 #13: pending Phase 2 for "DIR130-JON" replacing #0
000 #8: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 28131s; lastdpd=-1s(seq in:0 out:0)
000 #6: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 27991s; lastdpd=-1s(seq in:0 out:0)
000 #7: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 28061s; lastdpd=-1s(seq in:0 out:0)
000 #4: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 27850s; lastdpd=-1s(seq in:0 out:0)
000 #11: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 28342s; lastdpd=-1s(seq in:0 out:0)
000 #3: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 27780s; lastdpd=-1s(seq in:0 out:0)
000 #5: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 27920s; lastdpd=-1s(seq in:0 out:0)
000 #2: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 27709s; lastdpd=-1s(seq in:0 out:0)
000 #12: "DIR130-JON":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established); EVENT_SA_REPLACE in 28412s; lastdpd=-1s(seq in:0 out:0)
000
netstat -rn shows that Openswan does have a route to the other private network:
Destination Gateway Genmask Flags MSS Window irtt Iface
192.168.99.0 192.168.23.1 255.255.255.0 UG 0 0 0 eth0
When I ping 192.168.99.1 (the LAN side of the DIR-130) I get:
root at myopenswanhost# ping 192.168.99.1
connect: Resource temporarily unavailable
Now auth.log starts to show new error (shown in bold)...and this series of transaction repeats.
Apr 8 10:42:44 localhost pluto[29484]: packet from 66.27.113.46:4500: received Vendor ID payload [RFC 3947] method set to=109
Apr 8 10:42:44 localhost pluto[29484]: packet from 66.27.113.46:4500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using method 109
Apr 8 10:42:44 localhost pluto[29484]: packet from 66.27.113.46:4500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but already using method 109
Apr 8 10:42:44 localhost pluto[29484]: packet from 66.27.113.46:4500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
Apr 8 10:42:44 localhost pluto[29484]: packet from 66.27.113.46:4500: received Vendor ID payload [Dead Peer Detection]
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: responding to Main Mode
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: STATE_MAIN_R1: sent MR1, expecting MI2
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: NAT-Traversal: Result using 3: i am NATed
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: STATE_MAIN_R2: sent MR2, expecting MI3
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: Main mode peer ID is ID_IPV4_ADDR: '66.27.113.46'
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: I did not send a certificate because I do not have one.
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_md5 group=modp1024}
Apr 8 10:42:44 localhost pluto[29484]: "DIR130-JON" #21: Informational Exchange message must be encrypted
Apr 8 10:42:54 localhost pluto[29484]: "DIR130-JON" #21: retransmitting in response to duplicate packet; already STATE_MAIN_R3
Apr 8 10:42:54 localhost pluto[29484]: "DIR130-JON" #21: Informational Exchange message must be encrypted
Apr 8 10:43:14 localhost pluto[29484]: "DIR130-JON" #21: retransmitting in response to duplicate packet; already STATE_MAIN_R3
Apr 8 10:43:15 localhost pluto[29484]: "DIR130-JON" #21: Informational Exchange message must be encrypted
Apr 8 10:43:20 localhost pluto[29484]: "DIR130-JON" #20: max number of retransmissions (2) reached STATE_QUICK_I1. No acceptable response to our first Quick Mode message: perhaps peer likes no proposal
Apr 8 10:43:20 localhost pluto[29484]: "DIR130-JON" #20: starting keying attempt 2 of an unlimited number
Apr 8 10:43:20 localhost pluto[29484]: "DIR130-JON" #22: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP to replace #20 {using isakmp#21}
Apr 8 10:43:20 localhost pluto[29484]: "DIR130-JON" #21: Informational Exchange message must be encrypted
Apr 8 10:43:50 localhost last message repeated 2 times
and tcpdump now shows phase 2 related packets all initiated by Openswan:
10:46:09.030401 IP 192.168.23.23.4500 > 66.27.f.g.4500: isakmp-nat-keep-alive
10:46:10.033687 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 2/others R oakley-quick[E]
10:46:10.033723 IP 192.168.23.23.500 > 66.27.f.g.500: isakmp: phase 1 I ident
10:46:10.059197 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I inf
10:46:14.072964 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I ident
10:46:14.073608 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 1 R ident
10:46:14.152624 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I ident
10:46:14.223007 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 1 R ident
10:46:14.285564 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I ident[E]
10:46:14.472516 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 1 R ident[E]
10:46:14.501446 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I inf
10:46:24.497065 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I ident[E]
10:46:24.497267 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 1 R ident[E]
10:46:24.523523 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I inf
10:46:29.524189 IP 192.168.23.23.4500 > 66.27.f.g.4500: isakmp-nat-keep-alive
10:46:44.518040 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I ident[E]
10:46:44.518327 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 1 R ident[E]
10:46:44.543993 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I inf
10:46:49.541535 IP 192.168.23.23.4500 > 66.27.f.g.4500: isakmp-nat-keep-alive
10:46:50.544470 IP 192.168.23.23.500 > 66.27.f.g.500: isakmp: phase 1 I ident
10:46:50.548206 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 2/others R oakley-quick[E]
10:46:50.578267 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I inf
10:47:00.577804 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 2/others R oakley-quick[E]
10:47:00.604185 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I inf
10:47:09.605322 IP 192.168.23.23.4500 > 66.27.f.g.4500: isakmp-nat-keep-alive
10:47:20.553018 IP 192.168.23.23.4500 > 66.27.f.g.4500: NONESP-encap: isakmp: phase 2/others R oakley-quick[E]
10:47:20.574353 IP 66.27.f.g.4500 > 192.168.23.23.4500: NONESP-encap: isakmp: phase 1 I inf
Not sure where to go from here. Let me know if you have any insight into all this. Hoping you have some ideas...thx
----- Original Message ----
From: Jacco de Leeuw <jacco2 at dds.nl>
To: users at openswan.org
Sent: Tuesday, April 8, 2008 1:55:38 AM
Subject: Re: [Openswan Users] Error: "initial Main Mode message received on 192.168.23.23:500 but no connection has been authorized"
BUI18 wrote:
> Here's an update. I opened up both port 500 and 4500 on the DIR-130 and
> on the other end's router. Now it looks like I get established but
> can't ping.
> Apr 7 17:55:31 localhost pluto[17646]: "DIR130-JON" #1: ignoring
> informational payload, type INVALID_ID_INFORMATION
The DIR-130 disconnects because there is something it does not like.
Check its log files. Perhaps the PSKs do not match?
Jacco
--
Jacco de Leeuw mailto:jacco2 at dds.nl
Zaandam, The Netherlands http://www.jacco2.dds.nl
____________________________________________________________________________________
You rock. That's why Blockbuster's offering you one month of Blockbuster Total Access, No Cost.
http://tc.deals.yahoo.com/tc/blockbuster/text5.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.openswan.org/pipermail/users/attachments/20080408/c3fbd20c/attachment-0001.html
More information about the Users
mailing list