[Openswan Users] xl2tpd timeout with clients behind nat

richard -rw- weinberger richard.weinberger at gmail.com
Sun Apr 5 10:46:02 EDT 2009 

hi list!

i'm using openswan-2.6.14-1.el5_2.1, xl2tpd-1.2.4-1 on centos 5.3
(kernel 2.6.18-128.1.1.el5).
my ipsec/l2tp setup works perfect as long no client is behind nat.
client version is windows xp service pack 3.

when a client is behind nat xl2tpd seems unable do send data to the
nat'ed client.
the openswan-server is not firewalled at all.

here the logs from a connection attempt an my configuration:

[root at openswan-server ~] # tcpdump -n -i eth0 host nat-device and not port 22
18:06:17.889925 IP nat-device.57713 > openswan-server.isakmp: isakmp:
phase 1 I ident
18:06:17.890489 IP openswan-server.isakmp > nat-device.57713: isakmp:
phase 1 R ident
18:06:18.119747 IP nat-device.57713 > openswan-server.isakmp: isakmp:
phase 1 I ident
18:06:18.130431 IP openswan-server.isakmp > nat-device.57713: isakmp:
phase 1 R ident
18:06:18.228043 IP nat-device.57677 > openswan-server.ipsec-nat-t:
NONESP-encap: isakmp: phase 1 I ident[E]
18:06:18.228431 IP openswan-server.ipsec-nat-t > nat-device.57677:
NONESP-encap: isakmp: phase 1 R ident[E]
18:06:18.288950 IP nat-device.57677 > openswan-server.ipsec-nat-t:
NONESP-encap: isakmp: phase 2/others I oakley-quick[E]
18:06:18.290973 IP openswan-server.ipsec-nat-t > nat-device.57677:
NONESP-encap: isakmp: phase 2/others R oakley-quick[E]
18:06:18.340035 IP nat-device.57677 > openswan-server.ipsec-nat-t:
NONESP-encap: isakmp: phase 2/others I oakley-quick[E]
18:06:18.346994 IP nat-device.57677 > openswan-server.ipsec-nat-t:
UDP-encap: ESP(spi=0x3f297720,seq=0x1), length 140
18:06:19.342013 IP nat-device.57677 > openswan-server.ipsec-nat-t:
UDP-encap: ESP(spi=0x3f297720,seq=0x2), length 140
18:06:20.351326 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0)
*FRAMING_CAP(AS) *BEARER_CAP() |...
18:06:20.351362 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](8/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(36547)
*RESULT_CODE(1/0 Timeout)
18:06:20.351598 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=0,Nr=1 ZLB
18:06:21.341116 IP nat-device.57677 > openswan-server.ipsec-nat-t:
UDP-encap: ESP(spi=0x3f297720,seq=0x3), length 140
18:06:21.341422 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=0,Nr=1 ZLB
18:06:21.351379 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0)
*FRAMING_CAP(AS) *BEARER_CAP() |...
18:06:21.351404 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](8/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(36547)
*RESULT_CODE(1/0 Timeout)
18:06:22.351456 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0)
*FRAMING_CAP(AS) *BEARER_CAP() |...
18:06:22.351486 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](8/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(36547)
*RESULT_CODE(1/0 Timeout)
18:06:23.351514 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0)
*FRAMING_CAP(AS) *BEARER_CAP() |...
18:06:23.351537 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](8/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(36547)
*RESULT_CODE(1/0 Timeout)
18:06:24.351574 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0)
*FRAMING_CAP(AS) *BEARER_CAP() |...
18:06:24.351602 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](8/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(36547)
*RESULT_CODE(1/0 Timeout)
18:06:25.361900 IP nat-device.57677 > openswan-server.ipsec-nat-t:
UDP-encap: ESP(spi=0x3f297720,seq=0x4), length 140
18:06:25.362184 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=0,Nr=1 ZLB
18:06:25.362218 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(4263)
*RESULT_CODE(1/0 Timeout)
18:06:26.363690 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(4263)
*RESULT_CODE(1/0 Timeout)
18:06:27.363763 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(4263)
*RESULT_CODE(1/0 Timeout)
18:06:28.363827 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(4263)
*RESULT_CODE(1/0 Timeout)
18:06:29.363889 IP openswan-server.l2tp > nat-device.l2tp:
l2tp:[TLS](9/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(4263)
*RESULT_CODE(1/0 Timeout)
18:06:30.347417 IP nat-device.57677 > openswan-server.ipsec-nat-t:
isakmp-nat-keep-alive
18:06:30.568056 IP nat-device.57677 > openswan-server.ipsec-nat-t:
NONESP-encap: isakmp: phase 2/others I inf[E]
18:06:30.568635 IP openswan-server.ipsec-nat-t > nat-device.57677:
NONESP-encap: isakmp: phase 2/others R inf[E]
18:06:30.572380 IP nat-device.57677 > openswan-server.ipsec-nat-t:
NONESP-encap: isakmp: phase 2/others I inf[E]
18:06:30.585209 IP openswan-server.ipsec-nat-t > nat-device.57677:
NONESP-encap: isakmp: phase 2/others R inf[E]

[root at openswan-server ~]# tail -n 0 -f /var/log/secure
Apr  5 18:06:17 openswan-server pluto[19800]: packet from
nat-device:57713: ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY
00000004]
Apr  5 18:06:17 openswan-server pluto[19800]: packet from
nat-device:57713: ignoring Vendor ID payload [FRAGMENTATION]
Apr  5 18:06:17 openswan-server pluto[19800]: packet from
nat-device:57713: received Vendor ID payload
[draft-ietf-ipsec-nat-t-ike-02_n] method set to=106
Apr  5 18:06:17 openswan-server pluto[19800]: packet from
nat-device:57713: ignoring Vendor ID payload [Vid-Initial-Contact]
Apr  5 18:06:17 openswan-server pluto[19800]: "L2TP-PSK"[5] nat-device
#5: responding to Main Mode from unknown peer nat-device
Apr  5 18:06:17 openswan-server pluto[19800]: "L2TP-PSK"[5] nat-device
#5: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Apr  5 18:06:17 openswan-server pluto[19800]: "L2TP-PSK"[5] nat-device
#5: STATE_MAIN_R1: sent MR1, expecting MI2
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[5] nat-device
#5: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike-02/03: peer
is NATed
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[5] nat-device
#5: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[5] nat-device
#5: STATE_MAIN_R2: sent MR2, expecting MI3
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[5] nat-device
#5: Main mode peer ID is ID_FQDN: '@camel'
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[5] nat-device
#5: switched from "L2TP-PSK" to "L2TP-PSK"
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: deleting connection "L2TP-PSK" instance with peer nat-device
{isakmp=#0/ipsec=#0}
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: new NAT mapping for #5, was nat-device:57713, now nat-device:57677
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: STATE_MAIN_R3: sent MR3, ISAKMP SA established
{auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha
group=modp2048}
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: peer client type is FQDN
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: Applying workaround for MS-818043 NAT-T bug
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: IDci was FQDN: \325\036\367 , using NAT_OA=10.0.2.15/32 as IDci
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: the peer proposed: openswan-server/32:17/1701 -> 10.0.2.15/32:17/0
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: alloc_bytes1() was mistakenly asked to malloc 0 bytes for
st_skey_ar in duplicate_state, please report to dev at openswan.org
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: alloc_bytes1() was mistakenly asked to malloc 0 bytes for
st_skey_er in duplicate_state, please report to dev at openswan.org
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: alloc_bytes1() was mistakenly asked to malloc 0 bytes for
st_skey_pi in duplicate_state, please report to dev at openswan.org
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#5: alloc_bytes1() was mistakenly asked to malloc 0 bytes for
st_skey_pr in duplicate_state, please report to dev at openswan.org
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#6: responding to Quick Mode proposal {msgid:cf6cf58d}
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#6:     us: openswan-server<openswan-server>[+S=C]:17/1701
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#6:   them: nat-device[@camel,+S=C]:17/1701===?
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#6: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#6: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting
QI2
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#6: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Apr  5 18:06:18 openswan-server pluto[19800]: "L2TP-PSK"[6] nat-device
#6: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP=>0xf4ed387e
<0x3f297720 xfrm=3DES_0-HMAC_MD5 NATOA=10.0.2.15 NATD=nat-device:57677
DPD=none}

[root at openswan-server ~]# tail -n 0 -f /var/log/messages
Apr  5 18:06:20 openswan-server xl2tpd[19843]: Connection 8 closed to
nat-device, port 1701 (Timeout)
Apr  5 18:06:25 openswan-server xl2tpd[19843]: Maximum retries
exceeded for tunnel 4263.  Closing.
Apr  5 18:06:25 openswan-server xl2tpd[19843]: Connection 9 closed to
nat-device, port 1701 (Timeout)

[root at openswan-server ~]# cat /etc/ipsec.conf
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=none
        # 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:172.16.0.0/12,%v4:192.168.0.0/16,%v4:!192.168.1.0/24

include /etc/ipsec.d/*.conf


[root at openswan-server ~]# cat /etc/ipsec.d/L2TP-PSK.conf
conn L2TP-PSK
        authby=secret
        pfs=no
        rekey=no
        keyingtries=3
        left=openswan-server
        leftprotoport=17/1701
        right=%any
        rightsubnet=vhost:%no,%priv
        rightprotoport=17/%any
        auto=add

[root at openswan-server ~]# cat /etc/xl2tpd/xl2tpd.conf
[global]
; listen-addr = 192.168.1.98
;
;debug tunnel = yes
;debug network = yes

[lns default]
ip range = 192.168.1.128-192.168.1.254
local ip = 192.168.1.99
require chap = yes
refuse pap = yes
require authentication = yes
name = openswan-server
ppp debug = yes
pppoptfile = /etc/ppp/options.xl2tpd
length bit = yes

are there any known issues with psk and nat?
i'm clueless why my configuration does not work with nat.

thanks,
//richard

p.s: please cc me. i'm not in the list.

More information about the Users mailing list