[Openswan Users] Issue with connecting back to openswan server

Thu Dec 20 11:00:25 EST 2012

I am sorry, you are correct, The issue is that I am unable to
reconnect, I get a gateway does not respond error on the mac side, and
the below logs on openswan.

On Wed, Dec 19, 2012 at 9:44 PM, Elison Niven
<elison.niven at elitecore.com> wrote:
> You did not mention what the issue is !
> Why do you have rekey=no in your config. You realize that once the SA
> expires, the connection will be down unless the other end rekeys?
>
>
> On Thu 20 Dec 2012 07:02:16 AM IST, Gregory Durham wrote:
>>
>> 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
>> _______________________________________________
>> Users at lists.openswan.org
>> https://lists.openswan.org/mailman/listinfo/users
>> Micropayments: https://flattr.com/thing/38387/IPsec-for-Linux-made-easy
>> Building and Integrating Virtual Private Networks with Openswan:
>> http://www.amazon.com/gp/product/1904811256/104-3099591-2946327?n=283155
>>
>>
>
> --
> Best Regards,
> Elison Niven