[Openswan Users] Issue with connecting back to openswan server
Elison Niven
elison.niven at elitecore.com
Thu Dec 20 00:44:46 EST 2012
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
More information about the Users
mailing list