[Openswan Users] Issue with connecting back to openswan server

Gregory Durham gregory.durham at gmail.com
Wed Dec 19 20:32:16 EST 2012 

Hello,
I seem to have an issue that I am having issues resolving, and cannot
tell where the issue is at. Env info:
centos 6.3
openswan Linux Openswan U2.6.38/K2.6.32-279.el6.x86_64 (netkey)

xl2tpd: xl2tpd-1.3.1-5.el6.x86_64

Mac os x default vpn client on 10.7 and 10.8.


I am unable to reproduce the error by hand, however it appears to
happen after some time of non use, this happens every other day or so.
The fix has been to service ipsec restart. Again, I have not been able
to nail down the issue:
I replace my originating IP address with My_IP and the openswan
server's ip with openswan_ip

Thanks,
Greg

Verbose logging:



==> /var/log/messages <==
Dec 20 01:16:04 centos63 xl2tpd[5966]: Maximum retries exceeded for
tunnel 39372.  Closing.
Dec 20 01:16:04 centos63 xl2tpd[5966]: Connection 42 closed to My_IP,
port 52544 (Timeout)

==> /var/log/secure <==
Dec 20 01:16:13 centos63 pluto[29573]: |
Dec 20 01:16:13 centos63 pluto[29573]: | next event EVENT_DPD in 0
seconds for #18
Dec 20 01:16:13 centos63 pluto[29573]: | *time to handle event
Dec 20 01:16:13 centos63 pluto[29573]: | handling event EVENT_DPD
Dec 20 01:16:13 centos63 pluto[29573]: | event after this is
EVENT_NAT_T_KEEPALIVE in 3 seconds
Dec 20 01:16:13 centos63 pluto[29573]: | processing connection
l2tp-psk[12] My_IP
Dec 20 01:16:13 centos63 pluto[29573]: | inserting event EVENT_DPD,
timeout in 15 seconds for #18
Dec 20 01:16:13 centos63 pluto[29573]: | state: 17 requesting event
none to be deleted by
/root/rpmbuild/BUILD/openswan-2.6.38/programs/pluto/dpd.c:201
Dec 20 01:16:13 centos63 pluto[29573]: | inserting event
EVENT_DPD_TIMEOUT, timeout in 30 seconds for #17
Dec 20 01:16:13 centos63 pluto[29573]: | sending 92 bytes for ISAKMP
notify through eth0:4500 to My_IP:4500 (using #17)
Dec 20 01:16:13 centos63 pluto[29573]: | next event
EVENT_NAT_T_KEEPALIVE in 3 seconds
Dec 20 01:16:13 centos63 pluto[29573]: |
Dec 20 01:16:13 centos63 pluto[29573]: | *received 92 bytes from
My_IP:4500 on eth0 (port=4500)
Dec 20 01:16:13 centos63 pluto[29573]: | **parse ISAKMP Message:
Dec 20 01:16:13 centos63 pluto[29573]: |    initiator cookie:
Dec 20 01:16:13 centos63 pluto[29573]: |   d6 d4 80 0b  24 cb 36 a2
Dec 20 01:16:13 centos63 pluto[29573]: |    responder cookie:
Dec 20 01:16:13 centos63 pluto[29573]: |   b9 c7 3c 8e  a5 e4 3f f3
Dec 20 01:16:13 centos63 pluto[29573]: |    next payload type: ISAKMP_NEXT_HASH
Dec 20 01:16:13 centos63 pluto[29573]: |    ISAKMP version: ISAKMP
Version 1.0 (rfc2407)
Dec 20 01:16:13 centos63 pluto[29573]: |    exchange type: ISAKMP_XCHG_INFO
Dec 20 01:16:13 centos63 pluto[29573]: |    flags: ISAKMP_FLAG_ENCRYPTION
Dec 20 01:16:13 centos63 pluto[29573]: |    message ID:  94 1f 0c 58
Dec 20 01:16:13 centos63 pluto[29573]: |    length: 92
Dec 20 01:16:13 centos63 pluto[29573]: |  processing version=1.0
packet with exchange type=ISAKMP_XCHG_INFO (5)
Dec 20 01:16:13 centos63 pluto[29573]: | ICOOKIE:  d6 d4 80 0b  24 cb 36 a2
Dec 20 01:16:13 centos63 pluto[29573]: | RCOOKIE:  b9 c7 3c 8e  a5 e4 3f f3
Dec 20 01:16:13 centos63 pluto[29573]: | state hash entry 7
Dec 20 01:16:13 centos63 pluto[29573]: | peer and cookies match on
#18, provided msgid 00000000 vs c454ebd5/00000000
Dec 20 01:16:13 centos63 pluto[29573]: | peer and cookies match on
#17, provided msgid 00000000 vs 00000000/00000000
Dec 20 01:16:13 centos63 pluto[29573]: | p15 state object #17 found,
in STATE_MAIN_R3
Dec 20 01:16:13 centos63 pluto[29573]: | processing connection
l2tp-psk[12] My_IP
Dec 20 01:16:13 centos63 pluto[29573]: | got payload
0x100(ISAKMP_NEXT_HASH) needed: 0x100 opt: 0x0
Dec 20 01:16:13 centos63 pluto[29573]: | ***parse ISAKMP Hash Payload:
Dec 20 01:16:13 centos63 pluto[29573]: |    next payload type: ISAKMP_NEXT_N
Dec 20 01:16:13 centos63 pluto[29573]: |    length: 24
Dec 20 01:16:13 centos63 pluto[29573]: | got payload
0x800(ISAKMP_NEXT_N) needed: 0x0 opt: 0x0
Dec 20 01:16:13 centos63 pluto[29573]: | ***parse ISAKMP Notification Payload:
Dec 20 01:16:13 centos63 pluto[29573]: |    next payload type: ISAKMP_NEXT_NONE
Dec 20 01:16:13 centos63 pluto[29573]: |    length: 32
Dec 20 01:16:13 centos63 pluto[29573]: |    DOI: ISAKMP_DOI_IPSEC
Dec 20 01:16:13 centos63 pluto[29573]: |    protocol ID: 1
Dec 20 01:16:13 centos63 pluto[29573]: |    SPI size: 16
Dec 20 01:16:13 centos63 pluto[29573]: |    Notify Message Type: R_U_THERE_ACK
Dec 20 01:16:13 centos63 pluto[29573]: | removing 8 bytes of padding
Dec 20 01:16:13 centos63 pluto[29573]: | info:  d6 d4 80 0b  24 cb 36
a2  b9 c7 3c 8e  a5 e4 3f f3
Dec 20 01:16:13 centos63 pluto[29573]: | info:  00 00 15 e6
Dec 20 01:16:13 centos63 pluto[29573]: | processing informational
R_U_THERE_ACK (36137)
Dec 20 01:16:13 centos63 pluto[29573]: | state: 17 requesting event
EVENT_DPD_TIMEOUT to be deleted by
/root/rpmbuild/BUILD/openswan-2.6.38/programs/pluto/dpd.c:542
Dec 20 01:16:13 centos63 pluto[29573]: | complete state transition
with STF_IGNORE
Dec 20 01:16:13 centos63 pluto[29573]: | * processed 0 messages from
cryptographic helpers
Dec 20 01:16:13 centos63 pluto[29573]: | next event
EVENT_NAT_T_KEEPALIVE in 3 seconds
Dec 20 01:16:13 centos63 pluto[29573]: | next event
EVENT_NAT_T_KEEPALIVE in 3 seconds
Dec 20 01:16:16 centos63 pluto[29573]: |
Dec 20 01:16:16 centos63 pluto[29573]: | next event
EVENT_NAT_T_KEEPALIVE in 0 seconds
Dec 20 01:16:16 centos63 pluto[29573]: | *time to handle event
Dec 20 01:16:16 centos63 pluto[29573]: | handling event EVENT_NAT_T_KEEPALIVE
Dec 20 01:16:16 centos63 pluto[29573]: | event after this is
EVENT_PENDING_PHASE2 in 11 seconds
Dec 20 01:16:16 centos63 pluto[29573]: | processing connection
l2tp-psk[12] My_IP
Dec 20 01:16:16 centos63 pluto[29573]: | processing connection
l2tp-psk[12] My_IP
Dec 20 01:16:16 centos63 pluto[29573]: | sending 1 bytes for NAT-T
Keep Alive through eth0:4500 to My_IP:4500 (using #18)
Dec 20 01:16:16 centos63 pluto[29573]: | processing connection
l2tp-psk[12] My_IP
Dec 20 01:16:16 centos63 pluto[29573]: | processing connection
l2tp-psk[12] My_IP
Dec 20 01:16:16 centos63 pluto[29573]: | sending 1 bytes for NAT-T
Keep Alive through eth0:4500 to My_IP:4500 (using #17)
Dec 20 01:16:16 centos63 pluto[29573]: | inserting event
EVENT_NAT_T_KEEPALIVE, timeout in 20 seconds
Dec 20 01:16:16 centos63 pluto[29573]: | next event
EVENT_PENDING_PHASE2 in 11 seconds
Dec 20 01:16:17 centos63 pluto[29573]: |
Dec 20 01:16:17 centos63 pluto[29573]: | *received 92 bytes from
My_IP:4500 on eth0 (port=4500)
Dec 20 01:16:17 centos63 pluto[29573]: | **parse ISAKMP Message:
Dec 20 01:16:17 centos63 pluto[29573]: |    initiator cookie:
Dec 20 01:16:17 centos63 pluto[29573]: |   d6 d4 80 0b  24 cb 36 a2
Dec 20 01:16:17 centos63 pluto[29573]: |    responder cookie:
Dec 20 01:16:17 centos63 pluto[29573]: |   b9 c7 3c 8e  a5 e4 3f f3
Dec 20 01:16:17 centos63 pluto[29573]: |    next payload type: ISAKMP_NEXT_HASH
Dec 20 01:16:17 centos63 pluto[29573]: |    ISAKMP version: ISAKMP
Version 1.0 (rfc2407)
Dec 20 01:16:17 centos63 pluto[29573]: |    exchange type: ISAKMP_XCHG_INFO
Dec 20 01:16:17 centos63 pluto[29573]: |    flags: ISAKMP_FLAG_ENCRYPTION
Dec 20 01:16:17 centos63 pluto[29573]: |    message ID:  b7 34 20 f1
Dec 20 01:16:17 centos63 pluto[29573]: |    length: 92
Dec 20 01:16:17 centos63 pluto[29573]: |  processing version=1.0
packet with exchange type=ISAKMP_XCHG_INFO (5)
Dec 20 01:16:17 centos63 pluto[29573]: | ICOOKIE:  d6 d4 80 0b  24 cb 36 a2
Dec 20 01:16:17 centos63 pluto[29573]: | RCOOKIE:  b9 c7 3c 8e  a5 e4 3f f3
Dec 20 01:16:17 centos63 pluto[29573]: | state hash entry 7
Dec 20 01:16:17 centos63 pluto[29573]: | peer and cookies match on
#18, provided msgid 00000000 vs c454ebd5/00000000
Dec 20 01:16:17 centos63 pluto[29573]: | peer and cookies match on
#17, provided msgid 00000000 vs 00000000/00000000
Dec 20 01:16:17 centos63 pluto[29573]: | p15 state object #17 found,
in STATE_MAIN_R3
Dec 20 01:16:17 centos63 pluto[29573]: | processing connection
l2tp-psk[12] My_IP
Dec 20 01:16:17 centos63 pluto[29573]: | got payload
0x100(ISAKMP_NEXT_HASH) needed: 0x100 opt: 0x0
Dec 20 01:16:17 centos63 pluto[29573]: | ***parse ISAKMP Hash Payload:
Dec 20 01:16:17 centos63 pluto[29573]: |    next payload type: ISAKMP_NEXT_D
Dec 20 01:16:17 centos63 pluto[29573]: |    length: 24
Dec 20 01:16:17 centos63 pluto[29573]: | got payload
0x1000(ISAKMP_NEXT_D) needed: 0x0 opt: 0x0
Dec 20 01:16:17 centos63 pluto[29573]: | ***parse ISAKMP Delete Payload:
Dec 20 01:16:17 centos63 pluto[29573]: |    next payload type: ISAKMP_NEXT_NONE
Dec 20 01:16:17 centos63 pluto[29573]: |    length: 28
Dec 20 01:16:17 centos63 pluto[29573]: |    DOI: ISAKMP_DOI_IPSEC
Dec 20 01:16:17 centos63 pluto[29573]: |    protocol ID: 1
Dec 20 01:16:17 centos63 pluto[29573]: |    SPI size: 16
Dec 20 01:16:17 centos63 pluto[29573]: |    number of SPIs: 1
Dec 20 01:16:17 centos63 pluto[29573]: | removing 12 bytes of padding
Dec 20 01:16:17 centos63 pluto[29573]: | ICOOKIE:  d6 d4 80 0b  24 cb 36 a2
Dec 20 01:16:17 centos63 pluto[29573]: | RCOOKIE:  b9 c7 3c 8e  a5 e4 3f f3
Dec 20 01:16:17 centos63 pluto[29573]: | state hash entry 7
Dec 20 01:16:17 centos63 pluto[29573]: | v1 peer and cookies match on
#18, provided msgid 00000000 vs c454ebd5
Dec 20 01:16:17 centos63 pluto[29573]: | v1 peer and cookies match on
#17, provided msgid 00000000 vs 00000000
Dec 20 01:16:17 centos63 pluto[29573]: | v1 state object #17 found, in
STATE_MAIN_R3
Dec 20 01:16:17 centos63 pluto[29573]: | processing connection
l2tp-psk[12] My_IP
Dec 20 01:16:17 centos63 pluto[29573]: "l2tp-psk"[12] My_IP #17:
received Delete SA payload: deleting ISAKMP State #17
Dec 20 01:16:17 centos63 pluto[29573]: | deleting state #17
Dec 20 01:16:17 centos63 pluto[29573]: | sending 92 bytes for delete
notify through eth0:4500 to My_IP:4500 (using #17)
Dec 20 01:16:17 centos63 pluto[29573]: | del:  d6 d4 80 0b  24 cb 36
a2  b9 c7 3c 8e  a5 e4 3f f3
Dec 20 01:16:17 centos63 pluto[29573]: packet from My_IP:4500:
received and ignored informational message
Dec 20 01:16:17 centos63 pluto[29573]: | complete state transition
with STF_IGNORE
Dec 20 01:16:17 centos63 pluto[29573]: | * processed 0 messages from
cryptographic helpers
Dec 20 01:16:17 centos63 pluto[29573]: | next event
EVENT_PENDING_PHASE2 in 10 seconds
Dec 20 01:16:17 centos63 pluto[29573]: | next event
EVENT_PENDING_PHASE2 in 10 seconds
Dec 20 01:16:17 centos63 pluto[29573]: |
Dec 20 01:16:17 centos63 pluto[29573]: | *received 76 bytes from
My_IP:4500 on eth0 (port=4500)
Dec 20 01:16:17 centos63 pluto[29573]: | **parse ISAKMP Message:
Dec 20 01:16:17 centos63 pluto[29573]: |    initiator cookie:
Dec 20 01:16:17 centos63 pluto[29573]: |   d6 d4 80 0b  24 cb 36 a2
Dec 20 01:16:17 centos63 pluto[29573]: |    responder cookie:
Dec 20 01:16:17 centos63 pluto[29573]: |   b9 c7 3c 8e  a5 e4 3f f3
Dec 20 01:16:17 centos63 pluto[29573]: |    next payload type: ISAKMP_NEXT_HASH
Dec 20 01:16:17 centos63 pluto[29573]: |    ISAKMP version: ISAKMP
Version 1.0 (rfc2407)
Dec 20 01:16:17 centos63 pluto[29573]: |    exchange type: ISAKMP_XCHG_INFO
Dec 20 01:16:17 centos63 pluto[29573]: |    flags: ISAKMP_FLAG_ENCRYPTION
Dec 20 01:16:17 centos63 pluto[29573]: |    message ID:  89 b0 e6 47
Dec 20 01:16:17 centos63 pluto[29573]: |    length: 76
Dec 20 01:16:17 centos63 pluto[29573]: |  processing version=1.0
packet with exchange type=ISAKMP_XCHG_INFO (5)
Dec 20 01:16:17 centos63 pluto[29573]: | ICOOKIE:  d6 d4 80 0b  24 cb 36 a2
Dec 20 01:16:17 centos63 pluto[29573]: | RCOOKIE:  b9 c7 3c 8e  a5 e4 3f f3
Dec 20 01:16:17 centos63 pluto[29573]: | state hash entry 7
Dec 20 01:16:17 centos63 pluto[29573]: | peer and cookies match on
#18, provided msgid 00000000 vs c454ebd5/00000000
Dec 20 01:16:17 centos63 pluto[29573]: | p15 state object not found
Dec 20 01:16:17 centos63 pluto[29573]: | ICOOKIE:  d6 d4 80 0b  24 cb 36 a2
Dec 20 01:16:17 centos63 pluto[29573]: | RCOOKIE:  00 00 00 00  00 00 00 00
Dec 20 01:16:17 centos63 pluto[29573]: | state hash entry 12
Dec 20 01:16:17 centos63 pluto[29573]: | v1 state object not found
Dec 20 01:16:17 centos63 pluto[29573]: packet from My_IP:4500:
Informational Exchange is for an unknown (expired?) SA with
MSGID:0x47e6b089
Dec 20 01:16:17 centos63 pluto[29573]: | - unknown SA's md->hdr.isa_icookie:
Dec 20 01:16:17 centos63 pluto[29573]: |   d6 d4 80 0b  24 cb 36 a2
Dec 20 01:16:17 centos63 pluto[29573]: | - unknown SA's md->hdr.isa_rcookie:
Dec 20 01:16:17 centos63 pluto[29573]: |   b9 c7 3c 8e  a5 e4 3f f3
Dec 20 01:16:17 centos63 pluto[29573]: | * processed 0 messages from
cryptographic helpers
Dec 20 01:16:17 centos63 pluto[29573]: | next event
EVENT_PENDING_PHASE2 in 10 seconds
Dec 20 01:16:17 centos63 pluto[29573]: | next event
EVENT_PENDING_PHASE2 in 10 seconds
Dec 20 01:16:18 centos63 pluto[29573]: |
Dec 20 01:16:18 centos63 pluto[29573]: | *received kernel message
Dec 20 01:16:18 centos63 pluto[29573]: | delete expired bare shunt
eroute openswan_ip/32:0 --17-> My_IP/32:0 => %pass (raw_eroute)
Dec 20 01:16:18 centos63 pluto[29573]: | raw_eroute result=1
Dec 20 01:16:18 centos63 pluto[29573]: | delete bare shunt: null pointer
Dec 20 01:16:18 centos63 pluto[29573]: | * processed 0 messages from
cryptographic helpers
Dec 20 01:16:18 centos63 pluto[29573]: | next event
EVENT_PENDING_PHASE2 in 9 seconds
Dec 20 01:16:18 centos63 pluto[29573]: | next event
EVENT_PENDING_PHASE2 in 9 seconds

Openswan config

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

# basic configuration
config setup
        # Debug-logging controls:  "none" for (almost) none, "all" for lots.
        klipsdebug=all
        plutodebug="control parsing"
        # For Red Hat Enterprise Linux and Fedora, leave protostack=netkey
        protostack=netkey
        nat_traversal=yes
        virtual_private=%v4:10.0.0.0/8,%v4:192.168.0.0/16,%4:172.16.0.0/12
        oe=off
        interfaces="%defaultroute"
        # Enable this if you see "failed to find any available worker"
        # nhelpers=0

conn l2tp-psk
        authby=secret
        pfs=no
        auto=add
        keyingtries=3
        rekey=no
        ikelifetime=8h
        type=transport
        keylife=1h
        left=%defaultroute
        leftprotoport=17/1701
        right=%any
        rightprotoport=17/0
        rightsubnet=vhost:%no,%priv
        dpddelay=15
        dpdtimeout=30
        dpdaction=clear
        forceencaps=yes


xl2tpd.conf:
[global]
ipsec saref = yes
listen-addr = pubip
force userspace = yes
[lns default]
local ip = ipaddress
ip range = range
require chap = yes
refuse pap = yes
require authentication = yes
ppp debug = yes
length bit = yes
pppoptfile = /etc/ppp/options.xl2tpd


options.xl2tpd
require-mschap-v2
ms-dns 8.8.8.8
asyncmap 0
auth
crtscts
lock
hide-password
modem
nodefaultroute
debug
name l2tpd
proxyarp
lcp-echo-interval 30
lcp-echo-failure 4

More information about the Users mailing list