[Openswan Users] Openswan pluto causes connection drop after 10s with Android IPsec/L2TP clients

René Mayrhofer rene at mayrhofer.eu.org
Thu Sep 1 08:23:36 EDT 2011 

Hi everybody,

It seems that openswan pluto is having problems with Android clients. The 
reproducible problem is that:

- The gateway is a fresh Debian Squeeze installation with backported openswan 
2.6.35-1, strongswan 4.4.1-6, and xl2tpd 1.2.7+dfsg-1. Kernel is standard 
2.6.32-5 with and without SAref patch applied.

- Android 2.3.4 can, with the built-in IPsec/L2TP client - configured 
"normally" via the settings GUI with either PSK or X.509 certificates - connect 
to an openswan/strongswan gateway with xl2tpd.

- With strongswan pluto, the connection remains stable once established.

- With openswan pluto and otherwise the same configuration (ipsec.conf, 
ipsec.secrets as attached), the connection is terminated after 10s. This is 
perfectly reproducible with NETKEY and MAST and happens every time.

Any ideas on what might go wrong here (the same happens with openswan under 
OpenWRT, btw)?

best regards,
Rene

Log of the connect/disconnect:

Sep  1 13:04:04 sesame-test-client pluto[3282]: packet from 85.127.196.7:500: 
received Vendor ID payload [RFC 3947] method set to=109 
Sep  1 13:04:04 sesame-test-client pluto[3282]: packet from 85.127.196.7:500: 
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but 
already using method 109
Sep  1 13:04:04 sesame-test-client pluto[3282]: packet from 85.127.196.7:500: 
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but 
already using method 109
Sep  1 13:04:04 sesame-test-client pluto[3282]: packet from 85.127.196.7:500: 
received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
Sep  1 13:04:04 sesame-test-client pluto[3282]: packet from 85.127.196.7:500: 
ignoring Vendor ID payload [FRAGMENTATION 80000000]
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: responding to Main Mode from unknown peer 85.127.196.7
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: STATE_MAIN_R1: sent MR1, expecting MI2
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: NAT-Traversal: Result using RFC 3947 (NAT-Traversal): peer is 
NATed
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: STATE_MAIN_R2: sent MR2, expecting MI3
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: Main mode peer ID is ID_DER_ASN1_DN: 'C=AT, ST=Upper Austria, 
L=Hagenberg, O=FH Hagenberg, OU=Mobile Computing, CN=test01, 
E=peter.riedl at students.fh-hagenberg.at'
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: no crl from issuer "C=AT, ST=Upper Austria, L=Attnang-
Puchheim, O=Gibraltar, OU=Gibraltar firewall development, CN=Gibraltar firewall 
CA (created at 1306910011), E=not specified" found (strict=no)
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: I am sending my cert
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: new NAT mapping for #2, was 85.127.196.7:500, now 
85.127.196.7:4500
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: STATE_MAIN_R3: sent MR3, ISAKMP SA established 
{auth=OAKLEY_RSA_SIG cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1024}
Sep  1 13:04:04 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: Dead Peer Detection (RFC 3706): not enabled because peer did 
not advertise it

====> For some reason, there are retransmits between Phase 1 and Phase 2 here.

Sep  1 13:04:14 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: retransmitting in response to duplicate packet; already 
STATE_MAIN_R3
Sep  1 13:04:24 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: retransmitting in response to duplicate packet; already 
STATE_MAIN_R3
Sep  1 13:04:34 sesame-test-client pluto[3282]: "l2tpCertRoadwarriors"[2] 
85.127.196.7 #2: discarding duplicate packet -- exhausted retransmission; 
already STATE_MAIN_R3

==> But the L2TP connection can be successfully established nonetheless.
==> From this point onwards, there are no more pluto messages, not even with 
plutodebug=all.

Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: control_finish: Peer requested 
tunnel 31326 twice, ignoring second one.
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: Connection established to 
85.127.196.7, 41945.  Local: 63701, Remote: 31326 (ref=0/0).  LNS session is 
'default'
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: start_pppd: I'm running: 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "/usr/sbin/pppd" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "passive" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "-detach" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "10.50.50.36:10.50.50.37" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "refuse-pap" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "auth" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "require-chap" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "name" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "gibraltar-l2tp" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "file" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "/etc/ppp/l2tpd-options" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: "/dev/pts/1" 
Sep  1 13:04:38 sesame-test-client xl2tpd[1478]: Call established with 
85.127.196.7, Local: 60801, Remote: 5043, Serial: 727662941
Sep  1 13:04:38 sesame-test-client pppd[3312]: pppd 2.4.5 started by root, uid 
0
Sep  1 13:04:38 sesame-test-client pppd[3312]: using channel 4
Sep  1 13:04:38 sesame-test-client pppd[3312]: Using interface ppp0
Sep  1 13:04:38 sesame-test-client pppd[3312]: Connect: ppp0 <--> /dev/pts/1
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [LCP ConfReq id=0x1 <mru 
1400> <asyncmap 0x0> <auth chap MD5> <magic 0xe4da93e3>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: rcvd [LCP ConfReq id=0x1 <mru 
1400> <asyncmap 0x0> <magic 0xcb46e672> <pcomp> <accomp>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [LCP ConfRej id=0x1 
<pcomp> <accomp>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: rcvd [LCP ConfAck id=0x1 <mru 
1400> <asyncmap 0x0> <auth chap MD5> <magic 0xe4da93e3>]connected
Sep  1 13:04:38 sesame-test-client pppd[3312]: rcvd [LCP ConfReq id=0x2 <mru 
1400> <asyncmap 0x0> <magic 0xcb46e672>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [LCP ConfAck id=0x2 <mru 
1400> <asyncmap 0x0> <magic 0xcb46e672>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [LCP EchoReq id=0x0 
magic=0xe4da93e3]
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [CHAP Challenge id=0x4a 
<485a122eff2bc0c5b4a7d9b81e9e19f0a50e0016fe5d>, name = "gibraltar-l2tp"]
Sep  1 13:04:38 sesame-test-client pppd[3312]: rcvd [LCP EchoRep id=0x0 
magic=0xcb46e672]
Sep  1 13:04:38 sesame-test-client pppd[3312]: rcvd [CHAP Response id=0x4a 
<d5cebfb6ce6e558d6bf20ed491871b96>, name = "test01"]
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [CHAP Success id=0x4a 
"Access granted"]
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [IPCP ConfReq id=0x1 <addr 
10.50.50.36>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: rcvd [CCP ConfReq id=0x1 
<deflate 15> <deflate(old#) 15> <bsd v1 15>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: Unsupported protocol 
'Compression Control Protocol' (0x80fd) received
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [LCP ProtRej id=0x2 80 fd 
01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Sep  1 13:04:38 sesame-test-client pppd[3312]: rcvd [IPCP ConfReq id=0x1 
<compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [IPCP ConfRej id=0x1 
<compress VJ 0f 01>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: rcvd [IPCP ConfAck id=0x1 <addr 
10.50.50.36>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: rcvd [IPCP ConfReq id=0x2 <addr 
0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [IPCP ConfNak id=0x2 <addr 
10.50.50.37> <ms-dns1 10.50.50.36> <ms-dns2 10.50.50.36>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: rcvd [IPCP ConfReq id=0x3 <addr 
10.50.50.37> <ms-dns1 10.50.50.36> <ms-dns2 10.50.50.36>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: sent [IPCP ConfAck id=0x3 <addr 
10.50.50.37> <ms-dns1 10.50.50.36> <ms-dns2 10.50.50.36>]
Sep  1 13:04:38 sesame-test-client pppd[3312]: Cannot determine ethernet 
address for proxy ARP
Sep  1 13:04:38 sesame-test-client pppd[3312]: local  IP address 10.50.50.36
Sep  1 13:04:38 sesame-test-client pppd[3312]: remote IP address 10.50.50.37
Sep  1 13:04:38 sesame-test-client pppd[3312]: Script /etc/ppp/ip-up started 
(pid 3315)
Sep  1 13:04:38 sesame-test-client pppd[3312]: Script /etc/ppp/ip-up finished 
(pid 3315), status = 0x0

Sep  1 13:04:49 sesame-test-client pppd[3312]: rcvd [LCP TermReq id=0x3 "User 
request"]
Sep  1 13:04:49 sesame-test-client pppd[3312]: LCP terminated by peer (User 
request)
Sep  1 13:04:49 sesame-test-client pppd[3312]: Connect time 0.2 minutes.
Sep  1 13:04:49 sesame-test-client pppd[3312]: Sent 0 bytes, received 0 bytes.
Sep  1 13:04:49 sesame-test-client pppd[3312]: Script /etc/ppp/ip-down started 
(pid 3321)
Sep  1 13:04:49 sesame-test-client pppd[3312]: sent [LCP TermAck id=0x3]
Sep  1 13:04:49 sesame-test-client pppd[3312]: Script /etc/ppp/ip-down finished 
(pid 3321), status = 0x0
Sep  1 13:04:49 sesame-test-client xl2tpd[1478]: result_code_avp: avp is 
incorrect size.  8 < 10
Sep  1 13:04:49 sesame-test-client xl2tpd[1478]: handle_avps: Bad exit status 
handling attribute 1 (Result Code) on mandatory packet.
Sep  1 13:04:49 sesame-test-client xl2tpd[1478]: Trustingly terminating pppd: 
sending TERM signal to pid 3312
Sep  1 13:04:49 sesame-test-client pppd[3312]: Terminating on signal 15
Sep  1 13:04:49 sesame-test-client pppd[3312]: Modem hangup
Sep  1 13:04:49 sesame-test-client pppd[3312]: Connection terminated.
Sep  1 13:04:49 sesame-test-client pppd[3312]: Exit.
Sep  1 13:04:49 sesame-test-client xl2tpd[1478]: pppd 3312 successfully 
terminated
Sep  1 13:04:49 sesame-test-client xl2tpd[1478]: Connection 31326 closed to 
85.127.196.7, port 41945 (Result Code: expected at least 10, got 8)
Sep  1 13:04:54 sesame-test-client xl2tpd[1478]: Unable to deliver closing 
message for tunnel 63701. Destroying anyway.

-------------- next part --------------
# ipsec.conf - strongSwan IPsec configuration file

# basic configuration

config setup
	plutodebug=all
	# crlcheckinterval=600
	# strictcrlpolicy=yes
	# cachecrls=yes
	nat_traversal=yes
	#charonstart=yes
	#plutostart=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
        virtual_private=%v4:10.0.0.0/8,%v4:172.16.0.0/12,%v4:192.168.0.0/16
        protostack=netkey
        oe=off

# Add connections here.

# Sample VPN connections

#conn sample-self-signed
#      left=%defaultroute
#      leftsubnet=10.1.0.0/16
#      leftcert=selfCert.der
#      leftsendcert=never
#      right=192.168.0.2
#      rightsubnet=10.2.0.0/16
#      rightcert=peerCert.der
#      auto=start

#conn sample-with-ca-cert
#      left=%defaultroute
#      leftsubnet=10.1.0.0/16
#      leftcert=myCert.pem
#      right=192.168.0.2
#      rightsubnet=10.2.0.0/16
#      rightid="C=CH, O=Linux strongSwan CN=peer name"
#      keyexchange=ikev2
#      auto=start

include /var/lib/strongswan/ipsec.conf.inc

conn %default
	dpdaction=clear
        dpddelay=1
        dpdtimeout=10

conn l2tpRoadwarriors
	left=80.120.3.97
        rightsubnet=vhost:%no,%priv
	right=%any
	authby=secret
	auto=add
	leftprotoport=17/1701
	rightprotoport=17/0
	compress=no
	pfs=no
	type=transport
	
conn l2tpWinRoadwarriors
	left=80.120.3.97
        rightsubnet=vhost:%no,%priv
	right=%any
	authby=secret
	auto=add
	leftprotoport=17/1701
	rightprotoport=17/1701
	compress=no
	pfs=no
	type=transport

conn l2tpCertRoadwarriors
	left=80.120.3.97
        rightsubnet=vhost:%no,%priv
	right=%any
	leftcert=gibraltar.pem
	authby=rsasig
	rightrsasigkey=%cert
	leftrsasigkey=%cert
	auto=add
	leftprotoport=17/1701
	rightprotoport=17/0
	compress=no
	pfs=no
	type=transport
	
conn l2tpCertWinRoadwarriors
	left=80.120.3.97
        rightsubnet=vhost:%no,%priv
	right=%any
	leftcert=gibraltar.pem
	authby=rsasig
	rightrsasigkey=%cert
	leftrsasigkey=%cert
	auto=add
	leftprotoport=17/1701
	rightprotoport=17/1701
	compress=no
	pfs=no
	type=transport
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 836 bytes
Desc: This is a digitally signed message part.
Url : http://lists.openswan.org/pipermail/users/attachments/20110901/a7d17e0a/attachment-0001.bin

More information about the Users mailing list