[Openswan Users] openswan/xl2tpd failing to create ppp sessions
Jonathon Padfield
jonathon.padfield at gmail.com
Sun Feb 26 05:31:53 EST 2012
I'm aiming to run a SAref enabled kernel on Ubuntu 11.10 (kernel 3.0.0-16 #28)
I've followed the instructions at
https://www.openswan.org/projects/openswan/wiki/Building_and_Installing_an_SAref_capable_KLIPS_version_for_DebianUbuntu
and applied the 0001/0002 patches for 2.6.38 with minor changes.
I was hoping to stick with a close to stock kernel & repeatable
process, so am using packages from
http://ppa.launchpad.net/openswan/openswan-testing/
(openswan_2.6.37-1xelerance1_i386.deb) and dkms to load the ipsec
module
The ipsec module builds and loads. dmesg below
[17527144.832681] klips_info:ipsec_init: KLIPS startup, Openswan KLIPS
IPsec stack version: 2.6.37
[17527144.832847] NET: Registered protocol family 15
[17527144.834556] registered KLIPS /proc/sys/net
[17527144.834564] klips_info:ipsec_alg_init: KLIPS alg v=0.8.1-0
(EALG_MAX=255, AALG_MAX=251)
[17527144.834569] klips_info:ipsec_alg_init: calling ipsec_alg_static_init()
[17527144.834576] ipsec_aes_init(alg_type=15 alg_id=12 name=aes): ret=0
[17527144.834582] ipsec_aes_init(alg_type=14 alg_id=9 name=aes_mac): ret=0
[17527144.834588] ipsec_3des_init(alg_type=15 alg_id=3 name=3des): ret=0
[17527144.834602] KLIPS cryptoapi interface: alg_type=15 alg_id=12
name=cbc(aes) keyminbits=128 keymaxbits=256, found(0)
[17527144.834611] KLIPS cryptoapi interface: alg_type=15 alg_id=253
name=cbc(twofish) keyminbits=128 keymaxbits=256, found(0)
[17527144.834618] KLIPS cryptoapi interface: alg_type=15 alg_id=252
name=cbc(serpent) keyminbits=128 keymaxbits=256, found(0)
[17527144.834626] KLIPS cryptoapi interface: alg_type=15 alg_id=6
name=cbc(cast5) keyminbits=128 keymaxbits=128, found(0)
[17527144.834634] KLIPS cryptoapi interface: alg_type=15 alg_id=7
name=cbc(blowfish) keyminbits=96 keymaxbits=448, found(0)
[17527144.834642] KLIPS cryptoapi interface: alg_type=15 alg_id=3
name=cbc(des3_ede) keyminbits=192 keymaxbits=192, found(0)
I copied the ipsec.d/examples/mast-l2tp-psk.conf to ipsec.conf, and
that now looks like
root at localhost:/etc# cat ipsec.conf | grep -v \#
config setup
interfaces="%defaultroute"
protostack=mast
nat_traversal=yes
virtual_private=%v4:10.0.0.0/8,%v4:192.168.0.0/16,%v4:172.16.0.0/12,%v4:!192.168.1.0/24:!192.168.2.0/24
conn L2TP-PSK-NAT
rightsubnet=vhost:%priv
also=L2TP-PSK-noNAT
conn L2TP-PSK-noNAT
authby=secret
pfs=no
auto=add
keyingtries=3
rekey=no
dpddelay=10
dpdtimeout=90
dpdaction=clear
ikelifetime=8h
keylife=1h
type=transport
sareftrack=yes
overlapip=yes
left=75.227.251.212
leftprotoport=17/1701
right=%any
rightprotoport=17/%any
ipsec starts but does issue a warning about "PF_KEY K_SADB_X_PLUMBIF
response for configure_mast_device" -- no idea what that means.
root at localhost:/etc# /etc/init.d/ipsec start
ipsec_setup: Starting Openswan IPsec 2.6.37...
ipsec_setup: Fixup of mtu on mast0 to 16260
Feb 26 09:56:14 localhost ipsec_setup: Starting Openswan IPsec 2.6.37...
Feb 26 09:56:14 localhost ipsec_setup: Using KLIPS/mast stack
Feb 26 09:56:15 localhost kernel: [17527393.917145] Intel AES-NI
instructions are not detected.
Feb 26 09:56:15 localhost kernel: [17527393.979925] Intel AES-NI
instructions are not detected.
Feb 26 09:56:15 localhost ipsec_setup: KLIPS debug `none'
Feb 26 09:56:15 localhost ipsec_setup: KLIPS mast0 on eth0
75.227.251.212/24 broadcast mtu 1500
Feb 26 09:56:15 localhost ipsec_setup: Fixup of mtu on mast0 to 16260
Feb 26 09:56:15 localhost ipsec_setup: ...Openswan IPsec started
Feb 26 09:56:15 localhost pluto: adjusting ipsec.d to /etc/ipsec.d
Feb 26 09:56:15 localhost ipsec__plutorun: adjusting ipsec.d to /etc/ipsec.d
Feb 26 09:56:15 localhost ipsec__plutorun: 002 added connection
description "L2TP-PSK-NAT"
Feb 26 09:56:15 localhost ipsec__plutorun: 002 added connection
description "L2TP-PSK-noNAT"
Feb 26 09:56:15 localhost ipsec__plutorun: 003 ERROR: PF_KEY
K_SADB_X_PLUMBIF response for configure_mast_device included errno
17: File exists
but apparently it's running just fine.
root at localhost:/etc# ipsec verify
Checking your system to see if IPsec got installed and started correctly:
Version check and ipsec on-path [OK]
Linux Openswan 2.6.37 (klips)
Checking for IPsec support in kernel [OK]
KLIPS: checking for NAT Traversal support [OK]
KLIPS: checking for OCF crypto offload support [OK]
Kernel: IPsec SAref kernel support [OK]
Kernel: IPsec SAref Bind kernel support [OK]
Checking that pluto is running [OK]
Pluto listening for IKE on udp 500 [OK]
Pluto listening for NAT-T on udp 4500 [OK]
Two or more interfaces found, checking IP forwarding [OK]
Checking NAT and MASQUERADEing
Checking for 'ip' command [OK]
Checking /bin/sh is not /bin/dash [OK]
Checking for 'iptables' command [OK]
Opportunistic Encryption Support [DISABLED]
xltpd is configured like this
root at localhost:/etc/xl2tpd# cat xl2tpd.conf | grep -v ^\;
[global] ; Global parameters:
ipsec saref = yes
debug network = yes
debug tunnel = yes
listen-addr = 75.227.251.212
[lns default] ; Our fallthrough LNS definition
ip range = 192.168.2.2-192.168.2.20 ; * Allocate from this IP range
local ip = 192.168.2.1 ; * Our local IP to use
length bit = yes ; * Use length bit in payload?
refuse pap = yes ; * Refuse PAP authentication
refuse chap = yes ; * Refuse CHAP authentication
require authentication = yes ; * Require peer to authenticate
ppp debug = yes ; * Turn on PPP debugging
pppoptfile = /etc/ppp/options.l2tpd.lns ; * ppp options file
and ppp options of
root at localhost:/etc/xl2tpd# cat /etc/ppp/options.l2tpd.lns
ipcp-accept-local
ipcp-accept-remote
noccp
auth
crtscts
idle 1800
mtu 1200
mru 1200
nodefaultroute
debug
dump
lock
proxyarp
require-mschap-v2
ms-dns 8.8.8.8
ms-dns 8.8.4.4
name MYVPN
Now running xl2tpd in debug mode does give a strange message
"setsockopt recvref[22]: Protocol not available"
root at localhost:/etc/xl2tpd# xl2tpd -D
xl2tpd[11146]: Enabling IPsec SAref processing for L2TP transport mode SAs
xl2tpd[11146]: IPsec SAref does not work with L2TP kernel mode yet,
enabling forceuserspace=yes
xl2tpd[11146]: setsockopt recvref[22]: Protocol not available
xl2tpd[11146]: This binary does not support kernel L2TP.
xl2tpd[11146]: xl2tpd version xl2tpd-1.2.8 started on localhost PID:11146
xl2tpd[11146]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
xl2tpd[11146]: Forked by Scott Balmos and David Stipp, (C) 2001
xl2tpd[11146]: Inherited by Jeff McAdams, (C) 2002
xl2tpd[11146]: Forked again by Xelerance (www.xelerance.com) (C) 2006
xl2tpd[11146]: Listening on IP address 75.227.251.212, port 1701
But attempting a login, ipsec seems to negotiate the connection fine
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
received Vendor ID payload [RFC 3947] method set to=109
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike] method set
to=110
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
ignoring unknown Vendor ID payload [8f8d83826d246b6fc7a8a6a428c11de8]
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
ignoring unknown Vendor ID payload [439b59f8ba676c4c7737ae22eab8f582]
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
ignoring unknown Vendor ID payload [4d1e0e136deafa34c4f3ea9f02ec7285]
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
ignoring unknown Vendor ID payload [80d0bb3def54565ee84645d4c85ce3ee]
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
ignoring unknown Vendor ID payload [9909b64eed937c6573de52ace952fa6b]
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108,
but already using method 110
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107,
but already using method 110
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106,
but already using method 110
Feb 26 10:02:59 localhost pluto[11061]: packet from xx.xx.xx.xx:500:
received Vendor ID payload [Dead Peer Detection]
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[1] xx.xx.xx.xx
#1: responding to Main Mode from unknown peer xx.xx.xx.xx
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[1] xx.xx.xx.xx
#1: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[1] xx.xx.xx.xx
#1: STATE_MAIN_R1: sent MR1, expecting MI2
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[1] xx.xx.xx.xx
#1: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike (MacOS X):
peer is NATed
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[1] xx.xx.xx.xx
#1: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[1] xx.xx.xx.xx
#1: STATE_MAIN_R2: sent MR2, expecting MI3
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[1] xx.xx.xx.xx
#1: ignoring informational payload, type IPSEC_INITIAL_CONTACT
msgid=00000000
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[1] xx.xx.xx.xx
#1: Main mode peer ID is ID_IPV4_ADDR: '192.168.1.122'
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[1] xx.xx.xx.xx
#1: switched from "L2TP-PSK-NAT" to "L2TP-PSK-NAT"
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: deleting connection "L2TP-PSK-NAT" instance with peer xx.xx.xx.xx
{isakmp=#0/ipsec=#0}
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: new NAT mapping for #1, was xx.xx.xx.xx:500, now xx.xx.xx.xx:4500
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: STATE_MAIN_R3: sent MR3, ISAKMP SA established
{auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha
group=modp1024}
Feb 26 10:02:59 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: Dead Peer Detection (RFC 3706): enabled
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: Applying workaround for Mac OS X NAT-OA bug, ignoring proposed
subnet
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: the peer proposed: 75.227.251.212/32:17/1701 ->
xx.xx.xx.xx/32:17/0
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: peer proposal was reject in a virtual connection policy because:
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: a private network virtual IP was required, but the proposed IP
did not match our list (virtual_private=)
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-noNAT"[1]
xx.xx.xx.xx #2: responding to Quick Mode proposal {msgid:308f4896}
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-noNAT"[1]
xx.xx.xx.xx #2: us: 75.227.251.212<75.227.251.212>[+S=C]:17/1701
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-noNAT"[1]
xx.xx.xx.xx #2: them: xx.xx.xx.xx[192.168.1.122,+S=C]:17/58376
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-noNAT"[1]
xx.xx.xx.xx #2: transition from state STATE_QUICK_R0 to state
STATE_QUICK_R1
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-noNAT"[1]
xx.xx.xx.xx #2: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed,
expecting QI2
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-noNAT"[1]
xx.xx.xx.xx #2: Dead Peer Detection (RFC 3706): enabled
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-noNAT"[1]
xx.xx.xx.xx #2: transition from state STATE_QUICK_R1 to state
STATE_QUICK_R2
Feb 26 10:03:01 localhost pluto[11061]: "L2TP-PSK-noNAT"[1]
xx.xx.xx.xx #2: STATE_QUICK_R2: IPsec SA established transport mode
{ESP=>0x05432902 <0xe78de960 xfrm=AES_128-HMAC_SHA1 NATOA=none
NATD=xx.xx.xx.xx:4500 DPD=enabled}
Feb 26 10:03:21 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: received Delete SA(0x05432902) payload: deleting IPSEC State #2
Feb 26 10:03:21 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: deleting connection "L2TP-PSK-noNAT" instance with peer
xx.xx.xx.xx {isakmp=#0/ipsec=#0}
Feb 26 10:03:21 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: received and ignored informational message
Feb 26 10:03:21 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx
#1: received Delete SA payload: deleting ISAKMP State #1
Feb 26 10:03:21 localhost pluto[11061]: "L2TP-PSK-NAT"[2] xx.xx.xx.xx:
deleting connection "L2TP-PSK-NAT" instance with peer xx.xx.xx.xx
{isakmp=#0/ipsec=#0}
Feb 26 10:03:21 localhost pluto[11061]: packet from xx.xx.xx.xx:4500:
received and ignored informational message
(END)
But the connection fails and the xl2ptd logs don't reveal anything obvious.
xl2tpd[11146]: get_call: allocating new tunnel for host xx.xx.xx.xx, port 58376.
xl2tpd[11146]: network_thread: recv packet from xx.xx.xx.xx, size =
60, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[11146]: get_call: allocating new tunnel for host xx.xx.xx.xx, port 58376.
xl2tpd[11146]: control_finish: Peer requested tunnel 12 twice,
ignoring second one.
xl2tpd[11146]: build_fdset: closing down tunnel 2729
xl2tpd[11146]: network_thread: recv packet from xx.xx.xx.xx, size =
60, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[11146]: get_call: allocating new tunnel for host xx.xx.xx.xx, port 58376.
xl2tpd[11146]: control_finish: Peer requested tunnel 12 twice,
ignoring second one.
xl2tpd[11146]: build_fdset: closing down tunnel 48411
xl2tpd[11146]: network_thread: select timeout
xl2tpd[11146]: network_thread: select timeout
xl2tpd[11146]: network_thread: select timeout
xl2tpd[11146]: network_thread: select timeout
xl2tpd[11146]: network_thread: recv packet from xx.xx.xx.xx, size =
60, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[11146]: get_call: allocating new tunnel for host xx.xx.xx.xx, port 58376.
xl2tpd[11146]: control_finish: Peer requested tunnel 12 twice,
ignoring second one.
xl2tpd[11146]: build_fdset: closing down tunnel 9653
xl2tpd[11146]: network_thread: select timeout
xl2tpd[11146]: Maximum retries exceeded for tunnel 35554. Closing.
xl2tpd[11146]: network_thread: recv packet from xx.xx.xx.xx, size =
60, tunnel = 0, call = 0 ref=0 refhim=0
xl2tpd[11146]: get_call: allocating new tunnel for host xx.xx.xx.xx, port 58376.
xl2tpd[11146]: control_finish: Peer requested tunnel 12 twice,
ignoring second one.
xl2tpd[11146]: build_fdset: closing down tunnel 30665
xl2tpd[11146]: build_fdset: closing down tunnel 35554
xl2tpd[11146]: Connection 12 closed to xx.xx.xx.xx, port 58376 (Timeout)
xl2tpd[11146]: network_thread: select timeout
xl2tpd[11146]: network_thread: select timeout
xl2tpd[11146]: network_thread: select timeout
xl2tpd[11146]: network_thread: select timeout
xl2tpd[11146]: network_thread: select timeout
xl2tpd[11146]: Unable to deliver closing message for tunnel 35554.
Destroying anyway.
I'd appreciate any advice or help on getting this to work,
-Jon
More information about the Users
mailing list