[Openswan Users] Only one side of tunnel completing initiation?

Fri Dec 19 17:11:51 EST 2008

Whoops. Sorry Peter, you'll get this twice.  I meant to send it to the list
however instead of just you.

Peter McGill wrote: 
> Dan Brown wrote:
> > #1: received Delete SA payload: replace IPSEC State #2 in 10 seconds
> > #1: received and ignored informational message
> > #1: received Delete SA payload: deleting ISAKMP State #1
> > : packet from 207.236.235.99:500: received and ignored informational
> message
> > : packet from 207.236.235.99:500: ignoring unknown Vendor ID payload
> > [424e455300000009]
> > : packet from 207.236.235.99:500: received Vendor ID payload [Dead
> Peer
> > Detection]
> > #3: responding to Main Mode
> > ...
> 
> Why are you getting Delete requests from the Nortel?
> Timestamps may have explained the output better.

Oh I suspect I accidently included a few lines from the previous connection
attempt.  This would have been when the other side with the Nortel router
restarted the connection from his end.

> > #2: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP {using isakmp#1}
> > #2: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
> > #2: STATE_QUICK_I2: sent QI2, IPsec SA established {ESP=>0xfe516ebd
> > <0x169858db xfrm=3DES_0-HMAC_SHA1 NATD=none DPD=none}
> 
> You do appear to be connecting properly here.

I hadn't turned on debugging until this morning and discovered this is
really just the beginning of the Phase 2 connection.  The Phase 2 connection
never completes as OpenSwan doesn't appear to accept either the proposal or
the config.  Phase 1 is supposed to be 3des-sha1-modp1024, and phase 2
aes128-sha1-modp1024.  It appears to attempt to use 3DES in phase 2 of the
connection however.

This is that last message and the next with debugging (control parsing) on.

Dec 19 15:07:43 blackhawk pluto[18479]: "p2p" #2: STATE_QUICK_I2: sent QI2,
IPsec SA established {ESP=>0xed7ef1a6 <0xb09eb0b5 xfrm=3DES_0-HMAC_SHA1
NATD=none DPD=none}
Dec 19 15:07:43 blackhawk pluto[18479]: | modecfg pull: noquirk policy:push
not-client
Dec 19 15:07:43 blackhawk pluto[18479]: | phase 1 is done, looking for phase
1 to unpend
Dec 19 15:07:43 blackhawk pluto[18479]: | next event EVENT_PENDING_PHASE2 in
118 seconds

Does this mean however it's still trying to establish phase 2 as 3DES or
attempting to be the server (eg. the first two lines).

After 120 seconds it then sends this:

Dec 19 15:09:41 blackhawk pluto[18479]: |  
Dec 19 15:09:41 blackhawk pluto[18479]: | *time to handle event
Dec 19 15:09:41 blackhawk pluto[18479]: | handling event
EVENT_PENDING_PHASE2
Dec 19 15:09:41 blackhawk pluto[18479]: | event after this is
EVENT_REINIT_SECRET in 3480 seconds
Dec 19 15:09:41 blackhawk pluto[18479]: | inserting event
EVENT_PENDING_PHASE2, timeout in 120 seconds
Dec 19 15:09:41 blackhawk pluto[18479]: | pending review: connection "p2p"
checked
Dec 19 15:09:41 blackhawk pluto[18479]: | next event EVENT_PENDING_PHASE2 in
120 seconds
Dec 19 15:09:42 blackhawk pluto[18479]: |  
Dec 19 15:09:42 blackhawk pluto[18479]: | *received 84 bytes from
207.236.235.99:500 on eth0 (port=500)
Dec 19 15:09:42 blackhawk pluto[18479]: | **parse ISAKMP Message:
Dec 19 15:09:42 blackhawk pluto[18479]: |    initiator cookie:
Dec 19 15:09:42 blackhawk pluto[18479]: |   40 d1 31 e8  07 94 dc 2d
Dec 19 15:09:42 blackhawk pluto[18479]: |    responder cookie:
Dec 19 15:09:42 blackhawk pluto[18479]: |   64 4b 70 1b  e2 dd 8b 07
Dec 19 15:09:42 blackhawk pluto[18479]: |    next payload type:
ISAKMP_NEXT_HASH
Dec 19 15:09:42 blackhawk pluto[18479]: |    ISAKMP version: ISAKMP Version
1.0
Dec 19 15:09:42 blackhawk pluto[18479]: |    exchange type: ISAKMP_XCHG_INFO
Dec 19 15:09:42 blackhawk pluto[18479]: |    flags: ISAKMP_FLAG_ENCRYPTION
Dec 19 15:09:42 blackhawk pluto[18479]: |    message ID:  d2 ef a1 ca
Dec 19 15:09:42 blackhawk pluto[18479]: |    length: 84
Dec 19 15:09:42 blackhawk pluto[18479]: |  processing packet with exchange
type=ISAKMP_XCHG_INFO (5)
Dec 19 15:09:42 blackhawk pluto[18479]: | ICOOKIE:  40 d1 31 e8  07 94 dc 2d
Dec 19 15:09:42 blackhawk pluto[18479]: | RCOOKIE:  64 4b 70 1b  e2 dd 8b 07
Dec 19 15:09:42 blackhawk pluto[18479]: | peer:  cf ec eb 63
Dec 19 15:09:42 blackhawk pluto[18479]: | state hash entry 16
Dec 19 15:09:42 blackhawk pluto[18479]: | peer and cookies match on #2,
provided msgid 00000000 vs 57c98b9c/00000000
Dec 19 15:09:42 blackhawk pluto[18479]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000/00000000
Dec 19 15:09:42 blackhawk pluto[18479]: | p15 state object #1 found, in
STATE_MAIN_I4
Dec 19 15:09:42 blackhawk pluto[18479]: | processing connection gof2citi-psk
Dec 19 15:09:42 blackhawk pluto[18479]: | ***parse ISAKMP Hash Payload:
Dec 19 15:09:42 blackhawk pluto[18479]: |    next payload type:
ISAKMP_NEXT_N
Dec 19 15:09:42 blackhawk pluto[18479]: |    length: 24
Dec 19 15:09:42 blackhawk pluto[18479]: | ***parse ISAKMP Notification
Payload:
Dec 19 15:09:42 blackhawk pluto[18479]: |    next payload type:
ISAKMP_NEXT_NONE
Dec 19 15:09:42 blackhawk pluto[18479]: |    length: 32
Dec 19 15:09:42 blackhawk pluto[18479]: |    DOI: ISAKMP_DOI_IPSEC
Dec 19 15:09:42 blackhawk pluto[18479]: |    protocol ID: 1
Dec 19 15:09:42 blackhawk pluto[18479]: |    SPI size: 16
Dec 19 15:09:42 blackhawk pluto[18479]: |    Notify Message Type: R_U_THERE
Dec 19 15:09:42 blackhawk pluto[18479]: | info:  40 d1 31 e8  07 94 dc 2d
64 4b 70 1b  e2 dd 8b 07
Dec 19 15:09:42 blackhawk pluto[18479]: |   06 2a b8 e0
Dec 19 15:09:42 blackhawk pluto[18479]: | processing informational R_U_THERE
(36136)
Dec 19 15:09:42 blackhawk pluto[18479]: | sending 84 bytes for ISAKMP notify
through eth0:500 to 207.236.235.99:500:
Dec 19 15:09:42 blackhawk pluto[18479]: | complete state transition with
STF_IGNORE
Dec 19 15:09:42 blackhawk pluto[18479]: | next event EVENT_PENDING_PHASE2 in
119 seconds

So by the looks of it it never matches up.  I'm not sure if it has to  do
with the lines:
Dec 19 15:11:42 blackhawk pluto[18479]: | peer and cookies match on #2,
provided msgid 00000000 vs 57c98b9c/00000000
Dec 19 15:11:42 blackhawk pluto[18479]: | peer and cookies match on #1,
provided msgid 00000000 vs 00000000/00000000

So my config now looks like this (Openswan 2.6.19 using netkey):

My config for the connection has been changed a little to:

conn p2p
        # connection defs
        authby=secret
        pfs=yes
        auto=start
        compress=no
        type=tunnel
        keylife=8h
        # Phase 1
        keyexchange=ike
        keyingtries=3
        rekey=yes
        ike=3des-sha1-modp1024,aes128-sha1-modp1024
        ikelifetime=8h
        # Phase 2
        esp=aes128-sha1-1024
        # connection peers/networks
        left=209.167.162.84
        leftnexthop=209.167.162.81
        leftsubnet=209.167.162.80/28
        right=207.236.235.99
        rightsubnet=199.43.146.0/24

________________________________________________
Dan Brown
danb at zu.com