[Openswan Users] Can't initiate "phase 2"

Wilfredo Pachón wilfredcom at gmail.com
Tue Apr 24 22:42:47 EDT 2012


Hello friends of the list, thanks for the great job

I'm new to openswan but the last week i need to create a VPN with
other office in the server i admin this is the problem if any one can
help me in any form:

I am trying to setup a VPN with Openswan and a CISCO ASA 5540 router,
i readed many documentation and for me based on this all is fine, but
this doesn't work.

First of all this are the config setup in the router:

Phase 1:
Auth Method: Preshared Key
Encryption Scheme: IKE
D-H G: Group 2 (1024 bit)
Encryption Algorithm: 3DES
Integrity Algorithm: SHA1
Aggressive Mode: No
Renegotiation time: 24h

Phase 2:
Encapsulating: ESP
Encryption Algorithm: 3DES
Integrity Algorithm: SHA1
Perfect Forward  Secrecy: No

My ipsec.conf based in this config are:

config setup
    plutodebug=none
    klipsdebug=none
    nat_traversal=no
    #virtual_private=%v4:10.0.0.0/8,%v4:192.168.0.0/16,%v4:172.16.0.0/12
    #interfaces=eth0
    oe = off
    protostack=netkey
    nhelpers = 0

conn net-super
    type=tunnel
    authby=secret                # Key exchange method
    left=190.147.229.2          # Public Internet IP address of the
    leftsubnet=192.168.100.0/24     # Subnet protected by the LEFT VPN device
    leftnexthop=%defaultroute    # correct in many situations
    right=190.26.216.13         # Public Internet IP address of
    rightsubnet=192.168.20.0/24      # Subnet protected by the RIGHT VPN device
    rightnexthop=%defaultroute   # correct in many situations
    auto=start                   # authorizes and starts this connection
    aggrmode=no
    rekey=yes
    keyingtries=2
    keyexchange=ike
    ike=3DES-SHA1-modp1024
    ikelifetime=24h
    phase2=esp
    phase2alg=3DES-SHA1
    keylife=3600s
    pfs=no

My ipsecsecrets file have:
190.147.229.2 190.26.216.13 : PSK "SECRET"

I start adding this config with:
 sudo ipsec auto --add net-super

Reload the secrets file:
sudo ipsec auto --rereadsecrets

AND finnaly start the connection:
sudo ipsec auto --up net-super

When this command is executed for a while is maintained in foreground,
after some seconds it terminate and display this:
104 "net-super" #6: STATE_MAIN_I1: initiate
003 "net-super" #6: ignoring Vendor ID payload [FRAGMENTATION c0000000]
106 "net-super" #6: STATE_MAIN_I2: sent MI2, expecting MR2
010 "net-super" #6: STATE_MAIN_I2: retransmission; will wait 20s for response
003 "net-super" #6: ignoring informational payload, type
INVALID_COOKIE msgid=00000000
003 "net-super" #6: received and ignored informational message
010 "net-super" #6: STATE_MAIN_I2: retransmission; will wait 40s for response
003 "net-super" #6: ignoring informational payload, type
INVALID_COOKIE msgid=00000000
003 "net-super" #6: received and ignored informational message
031 "net-super" #6: max number of retransmissions (2) reached STATE_MAIN_I2
000 "net-super" #6: starting keying attempt 2 of at most 2, but releasing whack

I understand that the connection failed and acording to other tutorial
i try the command: "sudo ipsec whack --name net-super --initiate"
instead "ipsec auto --up" (but before i down all with sudo ipsec auto
--down net-super), with this the messages appeared more fast but with
similar results:
002 "net-super" #8: initiating Main Mode
104 "net-super" #8: STATE_MAIN_I1: initiate
003 "net-super" #8: ignoring Vendor ID payload [FRAGMENTATION c0000000]
002 "net-super" #8: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
106 "net-super" #8: STATE_MAIN_I2: sent MI2, expecting MR2
010 "net-super" #8: STATE_MAIN_I2: retransmission; will wait 20s for response
003 "net-super" #8: ignoring informational payload, type
INVALID_COOKIE msgid=00000000
003 "net-super" #8: received and ignored informational message
010 "net-super" #8: STATE_MAIN_I2: retransmission; will wait 40s for response
003 "net-super" #8: ignoring informational payload, type
INVALID_COOKIE msgid=00000000
003 "net-super" #8: received and ignored informational message
031 "net-super" #8: max number of retransmissions (2) reached STATE_MAIN_I2
000 "net-super" #8: starting keying attempt 2 of at most 2, but releasing whack


Trying to identify what happend i see the status: "sudo ipsec auto
--status", and this is part of the output:
000 using kernel interface: netkey
000 interface lo/lo ::1
000 interface lo/lo 127.0.0.1
000 interface eth1/eth1 192.168.10.10
000 interface eth2/eth2 192.168.100.1
000 interface eth0/eth0 190.147.229.2
000 %myid = (none)
000 debug parsing+control
000
000 virtual_private (%priv):
000 - allowed 0 subnets:
000 - disallowed 0 subnets:
000 WARNING: Either virtual_private= was not specified, or there was a syntax
000          error in that line. 'left/rightsubnet=%priv' will not work!
000
000 algorithm ESP encrypt: id=2, name=ESP_DES, ivlen=8, keysizemin=64,
keysizemax=64
000 algorithm ESP encrypt: id=3, name=ESP_3DES, ivlen=8,
keysizemin=192, keysizemax=192
...
000 algorithm ESP auth attr: id=1, name=AUTH_ALGORITHM_HMAC_MD5,
keysizemin=128, keysizemax=128
000 algorithm ESP auth attr: id=2, name=AUTH_ALGORITHM_HMAC_SHA1,
keysizemin=160, keysizemax=160
000 algorithm ESP auth attr: id=5, name=AUTH_ALGORITHM_HMAC_SHA2_256,
keysizemin=256, keysizemax=256
...
000 algorithm ESP auth attr: id=251, name=(null), keysizemin=0, keysizemax=0
000
000 algorithm IKE encrypt: id=0, name=(null), blocksize=16, keydeflen=131
000 algorithm IKE encrypt: id=3, name=OAKLEY_BLOWFISH_CBC,
blocksize=8, keydeflen=128
000 algorithm IKE encrypt: id=5, name=OAKLEY_3DES_CBC, blocksize=8,
keydeflen=192
...
000 stats db_ops: {curr_cnt, total_cnt, maxsz} :context={0,7,36}
trans={0,7,1152} attrs={0,7,1536}
000
000 "net-super":
192.168.2.0/24===190.147.229.25<190.147.229.25>[+S=C]---190.147.229.1...190.147.229.1---190.26.216.138<190.26.216.138>[+S=C]===192.168.202.0/24;
unrouted; eroute owner: #0
000 "net-super":     myip=unset; hisip=unset;
000 "net-super":   ike_life: 86400s; ipsec_life: 3600s; rekey_margin:
540s; rekey_fuzz: 100%; keyingtries: 2
000 "net-super":   policy: PSK+ENCRYPT+TUNNEL+UP+IKEv2ALLOW+lKOD+rKOD;
prio: 24,24; interface: eth0;
000 "net-super":   newest ISAKMP SA: #0; newest IPsec SA: #0;
000 "net-super":   IKE algorithms wanted:
3DES_CBC(5)_000-SHA1(2)-MODP1024(2); flags=-strict
000 "net-super":   IKE algorithms found:  3DES_CBC(5)_192-SHA1(2)_160-2,
000 "net-super":   ESP algorithms wanted: 3DES(3)_000-SHA1(2); flags=-strict
000 "net-super":   ESP algorithms loaded: 3DES(3)_192-SHA1(2)_160
000
000


And in /var/log/auth.log the relevant parts are:
Apr 24 21:19:51 ptpp pluto[23605]: | *received whack message
Apr 24 21:19:51 ptpp pluto[23605]: | processing connection net-super
Apr 24 21:19:51 ptpp pluto[23605]: | kernel_alg_db_new() will return
p_new->protoid=3, p_new->trans_cnt=1
Apr 24 21:19:51 ptpp pluto[23605]: | kernel_alg_db_new()     trans[0]:
transid=3, attr_cnt=1, attrs[0].type=5, attrs[0].val=2
Apr 24 21:19:51 ptpp pluto[23605]: | returning new proposal from esp_info
Apr 24 21:19:51 ptpp pluto[23605]: | creating state object #8 at 0x9e22498
Apr 24 21:19:51 ptpp pluto[23605]: | processing connection net-super
Apr 24 21:19:51 ptpp pluto[23605]: | ICOOKIE:  47 04 1d 92  57 3d cf 76
Apr 24 21:19:51 ptpp pluto[23605]: | RCOOKIE:  00 00 00 00  00 00 00 00
Apr 24 21:19:51 ptpp pluto[23605]: | state hash entry 31
Apr 24 21:19:51 ptpp pluto[23605]: | inserting state object #8 on chain 31
Apr 24 21:19:51 ptpp pluto[23605]: | inserting event EVENT_SO_DISCARD,
timeout in 0 seconds for #8
Apr 24 21:19:51 ptpp pluto[23605]: | processing connection net-super
Apr 24 21:19:51 ptpp pluto[23605]: | Queuing pending Quick Mode with
190.26.216.138 "net-super"
Apr 24 21:19:51 ptpp pluto[23605]: "net-super" #8: initiating Main Mode
Apr 24 21:19:51 ptpp pluto[23605]: | sending 120 bytes for main_outI1
through eth0:500 to 190.26.216.138:500 (using #8)
Apr 24 21:19:51 ptpp pluto[23605]: | inserting event EVENT_RETRANSMIT,
timeout in 10 seconds for #8
Apr 24 21:19:51 ptpp pluto[23605]: | * processed 0 messages from
cryptographic helpers
Apr 24 21:19:51 ptpp pluto[23605]: | next event EVENT_PENDING_DDNS in 3 seconds
Apr 24 21:19:51 ptpp pluto[23605]: | next event EVENT_PENDING_DDNS in 3 seconds
Apr 24 21:19:51 ptpp pluto[23605]: |
Apr 24 21:19:51 ptpp pluto[23605]: | *received 108 bytes from
190.26.216.138:500 on eth0 (port=500)
Apr 24 21:19:51 ptpp pluto[23605]: | **parse ISAKMP Message:
Apr 24 21:19:51 ptpp pluto[23605]: |    initiator cookie:
Apr 24 21:19:51 ptpp pluto[23605]: |   47 04 1d 92  57 3d cf 76
Apr 24 21:19:51 ptpp pluto[23605]: |    responder cookie:
Apr 24 21:19:51 ptpp pluto[23605]: |   dc 94 ca 46  64 8d 97 57
Apr 24 21:19:51 ptpp pluto[23605]: |    next payload type: ISAKMP_NEXT_SA
Apr 24 21:19:51 ptpp pluto[23605]: |    ISAKMP version: ISAKMP Version
1.0 (rfc2407)
Apr 24 21:19:51 ptpp pluto[23605]: |    exchange type: ISAKMP_XCHG_IDPROT
Apr 24 21:19:51 ptpp pluto[23605]: |    flags: none
Apr 24 21:19:51 ptpp pluto[23605]: |    message ID:  00 00 00 00
Apr 24 21:19:51 ptpp pluto[23605]: |    length: 108
Apr 24 21:19:51 ptpp pluto[23605]: |  processing version=1.0 packet
with exchange type=ISAKMP_XCHG_IDPROT (2)
Apr 24 21:19:51 ptpp pluto[23605]: | ICOOKIE:  47 04 1d 92  57 3d cf 76
Apr 24 21:19:51 ptpp pluto[23605]: | RCOOKIE:  dc 94 ca 46  64 8d 97 57
Apr 24 21:19:51 ptpp pluto[23605]: | state hash entry 4
Apr 24 21:19:51 ptpp pluto[23605]: | v1 state object not found
Apr 24 21:19:51 ptpp pluto[23605]: | ICOOKIE:  47 04 1d 92  57 3d cf 76
Apr 24 21:19:51 ptpp pluto[23605]: | RCOOKIE:  00 00 00 00  00 00 00 00
Apr 24 21:19:51 ptpp pluto[23605]: | state hash entry 31
Apr 24 21:19:51 ptpp pluto[23605]: | v1 peer and cookies match on #8,
provided msgid 00000000 vs 00000000
Apr 24 21:19:51 ptpp pluto[23605]: | v1 state object #8 found, in STATE_MAIN_I1
Apr 24 21:19:51 ptpp pluto[23605]: | processing connection net-super
Apr 24 21:19:51 ptpp pluto[23605]: | got payload 0x2(ISAKMP_NEXT_SA)
needed: 0x2 opt: 0x2080
Apr 24 21:19:51 ptpp pluto[23605]: | ***parse ISAKMP Security
Association Payload:
Apr 24 21:19:51 ptpp pluto[23605]: |    next payload type: ISAKMP_NEXT_VID
Apr 24 21:19:51 ptpp pluto[23605]: |    length: 56
Apr 24 21:19:51 ptpp pluto[23605]: |    DOI: ISAKMP_DOI_IPSEC
Apr 24 21:19:51 ptpp pluto[23605]: | got payload
0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x2080
Apr 24 21:19:51 ptpp pluto[23605]: | ***parse ISAKMP Vendor ID Payload:
Apr 24 21:19:51 ptpp pluto[23605]: |    next payload type: ISAKMP_NEXT_NONE
Apr 24 21:19:51 ptpp pluto[23605]: |    length: 24
Apr 24 21:19:51 ptpp pluto[23605]: "net-super" #8: ignoring Vendor ID
payload [FRAGMENTATION c0000000]
Apr 24 21:19:51 ptpp pluto[23605]: | ****parse IPsec DOI SIT:
Apr 24 21:19:51 ptpp pluto[23605]: |    IPsec DOI SIT: SIT_IDENTITY_ONLY
Apr 24 21:19:51 ptpp pluto[23605]: | ****parse ISAKMP Proposal Payload:
Apr 24 21:19:51 ptpp pluto[23605]: |    next payload type: ISAKMP_NEXT_NONE
Apr 24 21:19:51 ptpp pluto[23605]: |    length: 44
Apr 24 21:19:51 ptpp pluto[23605]: |    proposal number: 1
Apr 24 21:19:51 ptpp pluto[23605]: |    protocol ID: PROTO_ISAKMP
Apr 24 21:19:51 ptpp pluto[23605]: |    SPI size: 0
Apr 24 21:19:51 ptpp pluto[23605]: |    number of transforms: 1
Apr 24 21:19:51 ptpp pluto[23605]: | *****parse ISAKMP Transform
Payload (ISAKMP):
Apr 24 21:19:51 ptpp pluto[23605]: |    next payload type: ISAKMP_NEXT_NONE
Apr 24 21:19:51 ptpp pluto[23605]: |    length: 36
Apr 24 21:19:51 ptpp pluto[23605]: |    transform number: 0
Apr 24 21:19:51 ptpp pluto[23605]: |    transform ID: KEY_IKE
Apr 24 21:19:51 ptpp pluto[23605]: | ******parse ISAKMP Oakley attribute:
Apr 24 21:19:51 ptpp pluto[23605]: |    af+type: OAKLEY_ENCRYPTION_ALGORITHM
Apr 24 21:19:51 ptpp pluto[23605]: |    length/value: 5
Apr 24 21:19:51 ptpp pluto[23605]: |    [5 is OAKLEY_3DES_CBC]
Apr 24 21:19:51 ptpp pluto[23605]: | ******parse ISAKMP Oakley attribute:
Apr 24 21:19:51 ptpp pluto[23605]: |    af+type: OAKLEY_HASH_ALGORITHM
Apr 24 21:19:51 ptpp pluto[23605]: |    length/value: 2
Apr 24 21:19:51 ptpp pluto[23605]: |    [2 is OAKLEY_SHA1]
Apr 24 21:19:51 ptpp pluto[23605]: | ******parse ISAKMP Oakley attribute:
Apr 24 21:19:51 ptpp pluto[23605]: |    af+type: OAKLEY_GROUP_DESCRIPTION
Apr 24 21:19:51 ptpp pluto[23605]: |    length/value: 2
Apr 24 21:19:51 ptpp pluto[23605]: |    [2 is OAKLEY_GROUP_MODP1024]
Apr 24 21:19:51 ptpp pluto[23605]: | ******parse ISAKMP Oakley attribute:
Apr 24 21:19:51 ptpp pluto[23605]: |    af+type: OAKLEY_AUTHENTICATION_METHOD
Apr 24 21:19:51 ptpp pluto[23605]: |    length/value: 1
Apr 24 21:19:51 ptpp pluto[23605]: |    [1 is OAKLEY_PRESHARED_KEY]
Apr 24 21:19:51 ptpp pluto[23605]: | started looking for secret for
190.147.229.2->190.26.216.13 of kind PPK_PSK
Apr 24 21:19:51 ptpp pluto[23605]: | actually looking for secret for
190.147.229.2->190.26.216.13 of kind PPK_PSK
Apr 24 21:19:51 ptpp pluto[23605]: | 1: compared key 190.26.216.13 to
190.147.229.2 / 190.26.216.13 -> 4
Apr 24 21:19:51 ptpp pluto[23605]: | 2: compared key 190.147.229.2 to
190.147.229.2 / 190.26.216.13 -> 12
Apr 24 21:19:51 ptpp pluto[23605]: | line 9: match=12
Apr 24 21:19:51 ptpp pluto[23605]: | best_match 0>12 best=0x9e1e138 (line=9)
Apr 24 21:19:51 ptpp pluto[23605]: | concluding with best_match=12
best=0x9e1e138 (lineno=9)
Apr 24 21:19:51 ptpp pluto[23605]: | ******parse ISAKMP Oakley attribute:
Apr 24 21:19:51 ptpp pluto[23605]: |    af+type: OAKLEY_LIFE_TYPE
Apr 24 21:19:51 ptpp pluto[23605]: |    length/value: 1
Apr 24 21:19:51 ptpp pluto[23605]: |    [1 is OAKLEY_LIFE_SECONDS]
Apr 24 21:19:51 ptpp pluto[23605]: | ******parse ISAKMP Oakley attribute:
Apr 24 21:19:51 ptpp pluto[23605]: |    af+type: OAKLEY_LIFE_DURATION
(variable length)
Apr 24 21:19:51 ptpp pluto[23605]: |    length/value: 4
Apr 24 21:19:51 ptpp pluto[23605]: |    long duration: 86400
Apr 24 21:19:51 ptpp pluto[23605]: | Oakley Transform 0 accepted
Apr 24 21:19:51 ptpp pluto[23605]: | helper -1 doing build_kenonce op id: 7
Apr 24 21:19:51 ptpp pluto[23605]: | processing connection net-super
Apr 24 21:19:51 ptpp pluto[23605]: | ICOOKIE:  47 04 1d 92  57 3d cf 76
Apr 24 21:19:51 ptpp pluto[23605]: | RCOOKIE:  00 00 00 00  00 00 00 00
Apr 24 21:19:51 ptpp pluto[23605]: | state hash entry 31
Apr 24 21:19:51 ptpp pluto[23605]: | ICOOKIE:  47 04 1d 92  57 3d cf 76
Apr 24 21:19:51 ptpp pluto[23605]: | RCOOKIE:  dc 94 ca 46  64 8d 97 57
Apr 24 21:19:51 ptpp pluto[23605]: | state hash entry 4
Apr 24 21:19:51 ptpp pluto[23605]: | inserting state object #8 on chain 4
Apr 24 21:19:51 ptpp pluto[23605]: | complete state transition with STF_OK
Apr 24 21:19:51 ptpp pluto[23605]: "net-super" #8: transition from
state STATE_MAIN_I1 to state STATE_MAIN_I2
Apr 24 21:19:51 ptpp pluto[23605]: | sending reply packet to
190.26.216.13:500 (from port 500)
Apr 24 21:19:51 ptpp pluto[23605]: | sending 180 bytes for
STATE_MAIN_I1 through eth0:500 to 190.26.216.13:500 (using #8)
Apr 24 21:19:51 ptpp pluto[23605]: | inserting event EVENT_RETRANSMIT,
timeout in 10 seconds for #8
Apr 24 21:19:51 ptpp pluto[23605]: "net-super" #8: STATE_MAIN_I2: sent
MI2, expecting MR2
Apr 24 21:19:51 ptpp pluto[23605]: | modecfg pull: noquirk policy:push
not-client
Apr 24 21:19:51 ptpp pluto[23605]: | phase 1 is done, looking for
phase 2 to unpend
Apr 24 21:19:51 ptpp pluto[23605]: | complete state transition with STF_INLINE
Apr 24 21:19:51 ptpp pluto[23605]: | * processed 0 messages from
cryptographic helpers
Apr 24 21:19:51 ptpp pluto[23605]: | next event EVENT_PENDING_DDNS in 3 seconds
Apr 24 21:19:51 ptpp pluto[23605]: | next event

I understand for this that phase 1 is finished ok, but the second
don't, but while? i don't have any idea.

please any one can help me, give me some clue, point me in some direction.

I'm runnig Openswan Version: 1:2.6.23+dfsg-1ubuntu1, in a Ubuntu
10.04.1 LTS with kernel Linux ptpp 2.6.32-35-generic-pae #78-Ubuntu
SMP

please help it's very important and urgent.


More information about the Users mailing list