[Openswan Users] phase I established, but the tunnel DON'T START

antonio tony at gaveta.net
Thu Oct 11 11:43:33 EDT 2007 

phase I established, but the tunnel don't start.

this is scenario:

linux _ opensan (cliente) ->modem/router ---------------------- 
internet  -------------- openswan(server)


Linux Openswan U2.4.9/K2.6.21.6 (netkey)

################## ipsec.conf ( linux _ opensan (cliente) ) ################
version 2.0     # conforms to second version of ipsec.conf specification

# basic configuration
config setup
        plutodebug="control"
        nat_traversal=yes
        interfaces=%defaultroute
        virtual_private=%v4:10.0.0.0/8,%v4:172.16.0.0/12,%v4:192.168.0.0/16

# Add connections here
conn tunel
        pfs=no
        type=tunnel
        auto=add
        auth=esp
        authby=secret
        left=%defaultroute
        leftnexthop=192.168.0.1
        leftid="@tunel-left"
        right=89.4.135.2
        rightid="@tunel-right"

# sample VPN connections, see /etc/ipsec.d/examples/

#Disable Opportunistic Encryption
include /etc/ipsec.d/examples/no_oe.conf



####################### ipsec.conf (openswan(server)) ####################

version 2.0     # conforms to second version of ipsec.conf specification

# basic configuration
config setup
        plutodebug="control"
        nat_traversal=yes
        interfaces="ipsec0=eth0 "
        virtual_private=%v4:10.0.0.0/8,%v4:172.16.0.0/12,%v4:192.168.0.0/16

# Add connections here

conn tunel
        pfs=no
        type=tunnel
        auto=add
        auth=esp
        authby=secret
        left=192.168.10.25
        right=192.168.10.1

conn tunel2
        pfs=no
        type=tunnel
        auto=add
        auth=esp
        authby=secret
        left=89.4.135.2
        leftid="@tunel-right"
        right=89.4.135.1
        rightnexthop=192.168.0.3
        rightid="@tunel-left"

# sample VPN connections, see /etc/ipsec.d/examples/

#Disable Opportunistic Encryption
include /etc/ipsec.d/examples/no_oe.conf

##################### log file (tail auth.log | grep "pluto"): 
##################


Oct 11 17:34:17 marces pluto[32718]: |
Oct 11 17:34:17 marces pluto[32718]: | *received 312 bytes from 
89.4.135.1:500 on eth0 (port=500)
Oct 11 17:34:17 marces pluto[32718]: |  processing packet with exchange 
type=ISAKMP_XCHG_IDPROT (2)
Oct 11 17:34:17 marces pluto[32718]: packet from 89.4.135.1:500: 
received Vendor ID payload [Openswan (this version) 2.4.9  
PLUTO_SENDS_VENDORID PLUTO_USES_KEYRR]
Oct 11 17:34:17 marces pluto[32718]: packet from 89.4.135.1:500: 
received Vendor ID payload [Dead Peer Detection]
Oct 11 17:34:17 marces pluto[32718]: packet from 89.4.135.1:500: 
received Vendor ID payload [RFC 3947] method set to=110
Oct 11 17:34:17 marces pluto[32718]: packet from 89.4.135.1:500: 
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but 
already using method 110
Oct 11 17:34:17 marces pluto[32718]: packet from 89.4.135.1:500: 
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but 
already using method 110
Oct 11 17:34:17 marces pluto[32718]: packet from 89.4.135.1:500: 
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, 
but already using method 110
Oct 11 17:34:17 marces pluto[32718]: packet from 89.4.135.1:500: 
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
Oct 11 17:34:17 marces pluto[32718]: | creating state object #1 at 0x5bda10
Oct 11 17:34:17 marces pluto[32718]: | processing connection tunel2
Oct 11 17:34:17 marces pluto[32718]: | ICOOKIE:  5f ad 74 5a  96 67 f9 c3
Oct 11 17:34:17 marces pluto[32718]: | RCOOKIE:  d7 51 27 ce  0e f1 d7 a1
Oct 11 17:34:17 marces pluto[32718]: | peer:  59 04 87 01
Oct 11 17:34:17 marces pluto[32718]: | state hash entry 2
Oct 11 17:34:17 marces pluto[32718]: | inserting event EVENT_SO_DISCARD, 
timeout in 0 seconds for #1
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: responding to Main Mode
Oct 11 17:34:17 marces pluto[32718]: | started looking for secret for 
@tunel-right->@tunel-left of kind PPK_PSK
Oct 11 17:34:17 marces pluto[32718]: | actually looking for secret for 
@tunel-right->@tunel-left of kind PPK_PSK
Oct 11 17:34:17 marces pluto[32718]: | 1: compared PSK @tunel-left to 
@tunel-right / @tunel-left -> 2
Oct 11 17:34:17 marces pluto[32718]: | 2: compared PSK @tunel-right to 
@tunel-right / @tunel-left -> 6
Oct 11 17:34:17 marces pluto[32718]: | best_match 0>6 best=0x5bbed0 (line=3)
Oct 11 17:34:17 marces pluto[32718]: | 1: compared PSK 0.0.0.0 to 
@tunel-right / @tunel-left -> 0
Oct 11 17:34:17 marces pluto[32718]: | 2: compared PSK 10.0.1.2 to 
@tunel-right / @tunel-left -> 0
Oct 11 17:34:17 marces pluto[32718]: | 1: compared PSK 192.168.10.1 to 
@tunel-right / @tunel-left -> 0
Oct 11 17:34:17 marces pluto[32718]: | 2: compared PSK 192.168.10.25 to 
@tunel-right / @tunel-left -> 0
Oct 11 17:34:17 marces pluto[32718]: | concluding with best_match=6 
best=0x5bbed0 (lineno=3)
Oct 11 17:34:17 marces pluto[32718]: | complete state transition with STF_OK
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: transition from state 
STATE_MAIN_R0 to state STATE_MAIN_R1
Oct 11 17:34:17 marces pluto[32718]: | sending reply packet to 
89.4.135.1:500 (from port=500)
Oct 11 17:34:17 marces pluto[32718]: | sending 136 bytes for 
STATE_MAIN_R0 through eth0:500 to 89.4.135.1:500:
Oct 11 17:34:17 marces pluto[32718]: | inserting event EVENT_RETRANSMIT, 
timeout in 10 seconds for #1
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: STATE_MAIN_R1: sent 
MR1, expecting MI2
Oct 11 17:34:17 marces pluto[32718]: | modecfg pull: noquirk policy:push 
not-client
Oct 11 17:34:17 marces pluto[32718]: | phase 1 is done, looking for 
phase 1 to unpend
Oct 11 17:34:17 marces pluto[32718]: | next event EVENT_RETRANSMIT in 10 
seconds for #1
Oct 11 17:34:17 marces pluto[32718]: |
Oct 11 17:34:17 marces pluto[32718]: | *received 284 bytes from 
89.4.135.1:500 on eth0 (port=500)
Oct 11 17:34:17 marces pluto[32718]: |  processing packet with exchange 
type=ISAKMP_XCHG_IDPROT (2)
Oct 11 17:34:17 marces pluto[32718]: | ICOOKIE:  5f ad 74 5a  96 67 f9 c3
Oct 11 17:34:17 marces pluto[32718]: | RCOOKIE:  d7 51 27 ce  0e f1 d7 a1
Oct 11 17:34:17 marces pluto[32718]: | peer:  59 04 87 01
Oct 11 17:34:17 marces pluto[32718]: | state hash entry 2
Oct 11 17:34:17 marces pluto[32718]: | peer and cookies match on #1, 
provided msgid 00000000 vs 00000000
Oct 11 17:34:17 marces pluto[32718]: | state object #1 found, in 
STATE_MAIN_R1
Oct 11 17:34:17 marces pluto[32718]: | processing connection tunel2
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: NAT-Traversal: Result 
using RFC 3947 (NAT-Traversal): peer is NATed
Oct 11 17:34:17 marces pluto[32718]: | inserting event 
EVENT_NAT_T_KEEPALIVE, timeout in 20 seconds
Oct 11 17:34:17 marces pluto[32718]: | 0: w->pcw_dead: 0 w->pcw_work: 0 
cnt: 1
Oct 11 17:34:17 marces pluto[32718]: | asking helper 0 to do 
build_kenonce op on seq: 1
Oct 11 17:34:17 marces pluto[32718]: | inserting event 
EVENT_CRYPTO_FAILED, timeout in 300 seconds for #1
Oct 11 17:34:17 marces pluto[32718]: | complete state transition with 
STF_SUSPEND
Oct 11 17:34:17 marces pluto[32718]: | next event EVENT_NAT_T_KEEPALIVE 
in 20 seconds
Oct 11 17:34:17 marces pluto[32731]: ! helper 0 doing build_kenonce op id: 1
Oct 11 17:34:17 marces pluto[32718]: | processing connection tunel2
Oct 11 17:34:17 marces pluto[32718]: | started looking for secret for 
@tunel-right->@tunel-left of kind PPK_PSK
Oct 11 17:34:17 marces pluto[32718]: | actually looking for secret for 
@tunel-right->@tunel-left of kind PPK_PSK
Oct 11 17:34:17 marces pluto[32718]: | 1: compared PSK @tunel-left to 
@tunel-right / @tunel-left -> 2
Oct 11 17:34:17 marces pluto[32718]: | 2: compared PSK @tunel-right to 
@tunel-right / @tunel-left -> 6
Oct 11 17:34:17 marces pluto[32718]: | best_match 0>6 best=0x5bbed0 (line=3)
Oct 11 17:34:17 marces pluto[32718]: | 1: compared PSK 0.0.0.0 to 
@tunel-right / @tunel-left -> 0
Oct 11 17:34:17 marces pluto[32718]: | 2: compared PSK 10.0.1.2 to 
@tunel-right / @tunel-left -> 0
Oct 11 17:34:17 marces pluto[32718]: | 1: compared PSK 192.168.10.1 to 
@tunel-right / @tunel-left -> 0
Oct 11 17:34:17 marces pluto[32718]: | 2: compared PSK 192.168.10.25 to 
@tunel-right / @tunel-left -> 0
Oct 11 17:34:17 marces pluto[32718]: | concluding with best_match=6 
best=0x5bbed0 (lineno=3)
Oct 11 17:34:17 marces pluto[32718]: | complete state transition with STF_OK
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: transition from state 
STATE_MAIN_R1 to state STATE_MAIN_R2
Oct 11 17:34:17 marces pluto[32718]: | sending reply packet to 
89.4.135.1:500 (from port=500)
Oct 11 17:34:17 marces pluto[32718]: | sending 284 bytes for 
STATE_MAIN_R1 through eth0:500 to 89.4.135.1:500:
Oct 11 17:34:17 marces pluto[32718]: | inserting event EVENT_RETRANSMIT, 
timeout in 10 seconds for #1
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: STATE_MAIN_R2: sent 
MR2, expecting MI3
Oct 11 17:34:17 marces pluto[32718]: | modecfg pull: noquirk policy:push 
not-client
Oct 11 17:34:17 marces pluto[32718]: | phase 1 is done, looking for 
phase 1 to unpend
Oct 11 17:34:17 marces pluto[32718]: | next event EVENT_RETRANSMIT in 10 
seconds for #1
Oct 11 17:34:17 marces pluto[32718]: |
Oct 11 17:34:17 marces pluto[32718]: | *received 68 bytes from 
89.4.135.1:4500 on eth0 (port=4500)
Oct 11 17:34:17 marces pluto[32718]: |  processing packet with exchange 
type=ISAKMP_XCHG_IDPROT (2)
Oct 11 17:34:17 marces pluto[32718]: | ICOOKIE:  5f ad 74 5a  96 67 f9 c3
Oct 11 17:34:17 marces pluto[32718]: | RCOOKIE:  d7 51 27 ce  0e f1 d7 a1
Oct 11 17:34:17 marces pluto[32718]: | peer:  59 04 87 01
Oct 11 17:34:17 marces pluto[32718]: | state hash entry 2
Oct 11 17:34:17 marces pluto[32718]: | peer and cookies match on #1, 
provided msgid 00000000 vs 00000000
Oct 11 17:34:17 marces pluto[32718]: | state object #1 found, in 
STATE_MAIN_R2
Oct 11 17:34:17 marces pluto[32718]: | processing connection tunel2
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: Main mode peer ID is 
ID_FQDN: '@tunel-left'
Oct 11 17:34:17 marces pluto[32718]: | offered CA: '%none'
Oct 11 17:34:17 marces pluto[32718]: | thinking about whether to send my 
certificate:
Oct 11 17:34:17 marces pluto[32718]: |   I have RSA key: 
OAKLEY_PRESHARED_KEY cert.type: CERT_NONE
Oct 11 17:34:17 marces pluto[32718]: |   sendcert: CERT_ALWAYSSEND and I 
did not get a certificate request
Oct 11 17:34:17 marces pluto[32718]: |   so do not send cert.
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: I did not send a 
certificate because I do not have one.
Oct 11 17:34:17 marces pluto[32718]: | complete state transition with STF_OK
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: transition from state 
STATE_MAIN_R2 to state STATE_MAIN_R3
Oct 11 17:34:17 marces pluto[32718]: | sending reply packet to 
89.4.135.1:500 (from port=500)
Oct 11 17:34:17 marces pluto[32718]: | processing connection tunel2
Oct 11 17:34:17 marces pluto[32718]: | sending 68 bytes for 
STATE_MAIN_R2 through eth0:4500 to 89.4.135.1:4500:
Oct 11 17:34:17 marces pluto[32718]: | inserting event EVENT_SA_REPLACE, 
timeout in 3330 seconds for #1
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: STATE_MAIN_R3: sent 
MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY 
cipher=oakley_3des_cbc_192 prf=oakley_md5 group=modp1536}
Oct 11 17:34:17 marces pluto[32718]: | modecfg pull: noquirk policy:push 
not-client
Oct 11 17:34:17 marces pluto[32718]: | phase 1 is done, looking for 
phase 1 to unpend
Oct 11 17:34:17 marces pluto[32718]: | next event EVENT_NAT_T_KEEPALIVE 
in 20 seconds
Oct 11 17:34:17 marces pluto[32718]: |
Oct 11 17:34:17 marces pluto[32718]: | *received 212 bytes from 
89.4.135.1:4500 on eth0 (port=4500)
Oct 11 17:34:17 marces pluto[32718]: |  processing packet with exchange 
type=ISAKMP_XCHG_QUICK (32)
Oct 11 17:34:17 marces pluto[32718]: | ICOOKIE:  5f ad 74 5a  96 67 f9 c3
Oct 11 17:34:17 marces pluto[32718]: | RCOOKIE:  d7 51 27 ce  0e f1 d7 a1
Oct 11 17:34:17 marces pluto[32718]: | peer:  59 04 87 01
Oct 11 17:34:17 marces pluto[32718]: | state hash entry 2
Oct 11 17:34:17 marces pluto[32718]: | peer and cookies match on #1, 
provided msgid c0338168 vs 00000000
Oct 11 17:34:17 marces pluto[32718]: | state object not found
Oct 11 17:34:17 marces pluto[32718]: | ICOOKIE:  5f ad 74 5a  96 67 f9 c3
Oct 11 17:34:17 marces pluto[32718]: | RCOOKIE:  d7 51 27 ce  0e f1 d7 a1
Oct 11 17:34:17 marces pluto[32718]: | peer:  59 04 87 01
Oct 11 17:34:17 marces pluto[32718]: | state hash entry 2
Oct 11 17:34:17 marces pluto[32718]: | peer and cookies match on #1, 
provided msgid 00000000 vs 00000000
Oct 11 17:34:17 marces pluto[32718]: | state object #1 found, in 
STATE_MAIN_R3
Oct 11 17:34:17 marces pluto[32718]: | processing connection tunel2
Oct 11 17:34:17 marces pluto[32718]: | peer client is 192.168.0.3
Oct 11 17:34:17 marces pluto[32718]: | peer client protocol/port is 0/0
Oct 11 17:34:17 marces pluto[32718]: | our client is 89.4.135.2
Oct 11 17:34:17 marces pluto[32718]: | our client protocol/port is 0/0
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: cannot respond to 
IPsec SA request because no connection is known for 
89.4.135.2[@tunel-right]...89.4.135.1[@tunel-left]===192.168.0.3/32
Oct 11 17:34:17 marces pluto[32718]: | complete state transition with (null)
Oct 11 17:34:17 marces pluto[32718]: "tunel2" #1: sending encrypted 
notification INVALID_ID_INFORMATION to 89.4.135.1:4500
Oct 11 17:34:17 marces pluto[32718]: | sending 60 bytes for notification 
packet through eth0:4500 to 89.4.135.1:4500:
Oct 11 17:34:17 marces pluto[32718]: | state transition function for 
STATE_QUICK_R0 failed: INVALID_ID_INFORMATION
Oct 11 17:34:17 marces pluto[32718]: | next event EVENT_NAT_T_KEEPALIVE 
in 20 seconds

More information about the Users mailing list