[Openswan Users] Openswan 2.6.26 breaks Mac OS X 10.6 IPSec/L2TP interop
Kevin Arunski
kevin.arunski at netwitness.com
Mon Jun 14 10:57:31 EDT 2010
I have Openswan 2.6.26 running on CentOS 5.X (kernel 2.6.18) using
netkey. It is providing an IPSec/L2TP service for Windows and Mac users
in a roadwarrior setup.
I've found that 2.6.26 has a bug triggered only in Mac OS 10.6 when a
user disconnects.
After disconnecting, the remote user cannot establish any connection
from their current IP address, using any L2TP/IPSec client, not just
10.6. It appears something is corrupted in the state of pluto at this
point, since the only fix appears to be restarting pluto.
Here are the logs from the initial session:
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: received Vendor ID payload [RFC 3947] method set to=109
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike] method set to=110
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: ignoring unknown Vendor ID payload [8f8d83826d246b6fc7a8a6a428c11de8]
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: ignoring unknown Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: ignoring unknown Vendor ID payload [4d1e0e136deafa34c4f3ea9f02ec7285]
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: ignoring unknown Vendor ID payload [80d0bb3def54565ee84645d4c85ce3ee]
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: ignoring unknown Vendor ID payload [9909b64eed937c6573de52ace952fa6b]
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but already using method 110
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but already using method 110
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 110
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:500: received Vendor ID payload [Dead Peer Detection]
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[1] XXX.XXX.XXX.XXX #3: responding to Main Mode from unknown peer XXX.XXX.XXX.XXX
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[1] XXX.XXX.XXX.XXX #3: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[1] XXX.XXX.XXX.XXX #3: STATE_MAIN_R1: sent MR1, expecting MI2
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[1] XXX.XXX.XXX.XXX #3: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike (MacOS X): peer is NATed
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[1] XXX.XXX.XXX.XXX #3: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[1] XXX.XXX.XXX.XXX #3: STATE_MAIN_R2: sent MR2, expecting MI3
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[1] XXX.XXX.XXX.XXX #3: Main mode peer ID is ID_IPV4_ADDR: '192.168.1.2'
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[1] XXX.XXX.XXX.XXX #3: switched from "L2TP-PSK-NAT" to "L2TP-PSK-NAT"
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: deleting connection "L2TP-PSK-NAT" instance with peer XXX.XXX.XXX.XXX {isakmp=#0/ipsec=#0}
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: new NAT mapping for #3, was XXX.XXX.XXX.XXX:500, now XXX.XXX.XXX.XXX:4500
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1024}
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: Dead Peer Detection (RFC 3706): enabled
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: ignoring informational payload, type IPSEC_INITIAL_CONTACT msgid=00000000
> Jun 14 09:27:07 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: received and ignored informational message
> Jun 14 09:27:08 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: the peer proposed: SSS.SSS.SSS.SSS/32:17/1701 -> 192.168.1.2/32:17/0
> Jun 14 09:27:08 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #4: responding to Quick Mode proposal {msgid:82f9ffaf}
> Jun 14 09:27:08 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #4: us: SSS.SSS.SSS.SSS<SSS.SSS.SSS.SSS>[+S=C]:17/1701
> Jun 14 09:27:08 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #4: them: XXX.XXX.XXX.XXX[192.168.1.2,+S=C]:17/55404===192.168.1.2/32
> Jun 14 09:27:08 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #4: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
> Jun 14 09:27:08 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #4: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
> Jun 14 09:27:08 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #4: Dead Peer Detection (RFC 3706): enabled
> Jun 14 09:27:08 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #4: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
> Jun 14 09:27:08 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #4: STATE_QUICK_R2: IPsec SA established transport mode {ESP=>0x0c92d313 <0x9b258dfa xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=XXX.XXX.XXX.XXX:4500 DPD=enabled}
> Jun 14 09:27:11 ipsec-l2tp-server pppd[12062]: authentication succeeds for 'USERNAME'
> Jun 14 09:43:27 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: received Delete SA(0x0c92d313) payload: deleting IPSEC State #4
> Jun 14 09:43:27 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: ERROR: netlink XFRM_MSG_DELPOLICY response for flow eroute_connection delete included errno 2: No such file or directory
> Jun 14 09:43:27 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: received and ignored informational message
> Jun 14 09:43:27 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX #3: received Delete SA payload: deleting ISAKMP State #3
> Jun 14 09:43:27 ipsec-l2tp-server pluto[11867]: "L2TP-PSK-NAT"[2] XXX.XXX.XXX.XXX: deleting connection "L2TP-PSK-NAT" instance with peer XXX.XXX.XXX.XXX {isakmp=#0/ipsec=#0}
> Jun 14 09:43:27 ipsec-l2tp-server pluto[11867]: packet from XXX.XXX.XXX.XXX:4500: received and ignored informational message
> Jun 14 09:43:28 ipsec-l2tp-server pluto[11867]: initiate on demand from SSS.SSS.SSS.SSS:1701 to XXX.XXX.XXX.XXX:55404 proto=17 state: fos_start because: acquire
> Jun 14 09:44:00 ipsec-l2tp-server pluto[11867]: initiate on demand from SSS.SSS.SSS.SSS:1701 to XXX.XXX.XXX.XXX:55404 proto=17 state: fos_start because: acquire
> Jun 14 09:45:04 ipsec-l2tp-server last message repeated 2 times
> Jun 14 09:45:36 ipsec-l2tp-server pluto[11867]: initiate on demand from SSS.SSS.SSS.SSS:1701 to XXX.XXX.XXX.XXX:55404 proto=17 state: fos_start because: acquire
Here are the logs from an unsuccessful connection attempt:
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[61] XXX.XXX.XXX.XXX #164: responding to Main Mode from unknown peer XXX.XXX.XXX.XXX
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[61] XXX.XXX.XXX.XXX #164: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[61] XXX.XXX.XXX.XXX #164: STATE_MAIN_R1: sent MR1, expecting MI2
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[61] XXX.XXX.XXX.XXX #164: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike (MacOS X): peer is NATed
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[61] XXX.XXX.XXX.XXX #164: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[61] XXX.XXX.XXX.XXX #164: STATE_MAIN_R2: sent MR2, expecting MI3
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[61] XXX.XXX.XXX.XXX #164: Main mode peer ID is ID_IPV4_ADDR: '192.168.1.2'
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[61] XXX.XXX.XXX.XXX #164: switched from "L2TP-PSK-NAT" to "L2TP-PSK-NAT"
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: deleting connection "L2TP-PSK-NAT" instance with peer XXX.XXX.XXX.XXX {isakmp=#0/ipsec=#0}
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: new NAT mapping for #164, was XXX.XXX.XXX.XXX:500, now XXX.XXX.XXX.XXX:4500
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1024}
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: Dead Peer Detection (RFC 3706): enabled
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: ignoring informational payload, type IPSEC_INITIAL_CONTACT msgid=00000000
> Jun 14 09:23:41 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: received and ignored informational message
> Jun 14 09:23:42 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: the peer proposed: SSS.SSS.SSS.SSS/32:17/1701 -> 192.168.1.2/32:17/0
> Jun 14 09:23:42 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #165: responding to Quick Mode proposal {msgid:b6580fae}
> Jun 14 09:23:42 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #165: us: SSS.SSS.SSS.SSS<SSS.SSS.SSS.SSS>[+S=C]:17/1701
> Jun 14 09:23:42 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #165: them: XXX.XXX.XXX.XXX[192.168.1.2,+S=C]:17/56807===192.168.1.2/32
> Jun 14 09:23:42 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #165: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
> Jun 14 09:23:42 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #165: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
> Jun 14 09:23:42 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #165: Dead Peer Detection (RFC 3706): enabled
> Jun 14 09:23:42 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #165: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
> Jun 14 09:23:42 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #165: STATE_QUICK_R2: IPsec SA established transport mode {ESP=>0x0bc3a002 <0x749d21a6 xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=XXX.XXX.XXX.XXX:4500 DPD=enabled}
> Jun 14 09:24:02 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: received Delete SA(0x0bc3a002) payload: deleting IPSEC State #165
> Jun 14 09:24:02 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: ERROR: netlink XFRM_MSG_DELPOLICY response for flow eroute_connection delete included errno 2: No such file or directory
> Jun 14 09:24:02 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: received and ignored informational message
> Jun 14 09:24:02 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX #164: received Delete SA payload: deleting ISAKMP State #164
> Jun 14 09:24:02 ipsec-l2tp-server pluto[2771]: "L2TP-PSK-NAT"[62] XXX.XXX.XXX.XXX: deleting connection "L2TP-PSK-NAT" instance with peer XXX.XXX.XXX.XXX {isakmp=#0/ipsec=#0}
> Jun 14 09:24:02 ipsec-l2tp-server pluto[2771]: packet from XXX.XXX.XXX.XXX:4500: received and ignored informational message
After The SA was established, I see this in xl2tpd's log:
> Jun 14 09:45:03 wsip-98-172-153-200 xl2tpd[10334]: Connection 19 closed to XXX.XXX.XXX.XXX, port 55404 (Timeout)
> Jun 14 09:45:34 wsip-98-172-153-200 xl2tpd[10334]: udp_xmit failed with err=-1:No such process
> Jun 14 09:46:06 wsip-98-172-153-200 last message repeated 3 times
--
KEVIN ARUNSKI
SENIOR SOFTWARE ENGINEER
NETWITNESS | 500 Grove Street, Suite 300 | Herndon, VA 20170
More information about the Users
mailing list