[Openswan Users] Android client disconnects after 10s

Thu Nov 24 05:00:58 EST 2011

 I have a problem similar to the one reported here.

  https://lists.openswan.org/pipermail/users/2011-September/020890.html

 While happy to finally manage to get ipsec/l2tp+cert working as such,
 I am not familiar enough with this to even guess which of the involved
 components or protocols are failing.

 Server is running Gentoo stable with openswan 2.6.37 and nss support, set
 up along the lines of http://en.gentoo-wiki.com/wiki/IPsec_L2TP_VPN_server
 and no firewall running (testing inside LAN). Client is running Android 2.3.x.
 rightprotoport=17/%any, btw., and an l2tp secret is used.

 What I'd like to know as well:
 - do I need to import the client cert into the server's nss db?
 - do I need to import the crl into the server's nss db?
 - a better way to debug this? I don't think I have access to any
   client side logs.

Nov 23 23:51:07 server pluto[24417]: packet from 192.168.1.11:500: received Vendor ID payload [RFC 3947] method set to=109 
Nov 23 23:51:07 server pluto[24417]: packet from 192.168.1.11:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but already using method 109
Nov 23 23:51:07 server pluto[24417]: packet from 192.168.1.11:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 109
Nov 23 23:51:07 server pluto[24417]: packet from 192.168.1.11:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
Nov 23 23:51:07 server pluto[24417]: packet from 192.168.1.11:500: ignoring Vendor ID payload [FRAGMENTATION 80000000]
Nov 23 23:51:07 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: responding to Main Mode from unknown peer 192.168.1.11
Nov 23 23:51:07 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Nov 23 23:51:07 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: STATE_MAIN_R1: sent MR1, expecting MI2
Nov 23 23:51:17 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: NAT-Traversal: Result using RFC 3947 (NAT-Traversal): no NAT detected
Nov 23 23:51:17 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Nov 23 23:51:17 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: STATE_MAIN_R2: sent MR2, expecting MI3
Nov 23 23:51:17 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: Main mode peer ID is ID_IPV4_ADDR: '192.168.1.11'
Nov 23 23:51:17 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: no crl from issuer "C=XX, ST=STATE, O=Org, CN=vpnsrv.org, E=EMAIL" found (strict=no)
Nov 23 23:51:17 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: no suitable connection for peer '192.168.1.11'
Nov 23 23:51:17 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: sending encrypted notification INVALID_ID_INFORMATION to 192.168.1.11:500
Nov 23 23:51:27 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: Main mode peer ID is ID_IPV4_ADDR: '192.168.1.11'
Nov 23 23:51:27 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: no crl from issuer "C=XX, ST=STATE, O=Org, CN=vpnsrv.org, E=EMAIL" found (strict=no)
Nov 23 23:51:27 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: no suitable connection for peer '192.168.1.11'
Nov 23 23:51:27 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: sending encrypted notification INVALID_ID_INFORMATION to 192.168.1.11:500
Nov 23 23:51:27 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: Main mode peer ID is ID_IPV4_ADDR: '192.168.1.11'
Nov 23 23:51:27 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: no crl from issuer "C=XX, ST=STATE, O=Org, CN=vpnsrv.org, E=EMAIL" found (strict=no)
Nov 23 23:51:27 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: no suitable connection for peer '192.168.1.11'
Nov 23 23:51:27 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: sending encrypted notification INVALID_ID_INFORMATION to 192.168.1.11:500
Nov 23 23:51:36 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: Main mode peer ID is ID_IPV4_ADDR: '192.168.1.11'
Nov 23 23:51:36 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: no crl from issuer "C=XX, ST=STATE, O=Org, CN=vpnsrv.org, E=EMAIL" found (strict=no)
Nov 23 23:51:36 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: no suitable connection for peer '192.168.1.11'
Nov 23 23:51:36 server pluto[24417]: "l2tp-X.509"[2] 192.168.1.11 #2: sending encrypted notification INVALID_ID_INFORMATION to 192.168.1.11:500
Nov 23 23:51:42 server xl2tpd[24594]: control_finish: Peer requested tunnel 14382 twice, ignoring second one.
Nov 23 23:51:42 server xl2tpd[24594]: Connection established to 192.168.1.11, 60782.  Local: 50153, Remote: 14382 (ref=0/0).  LNS session is 'default'
Nov 23 23:51:42 server xl2tpd[24594]: start_pppd: I'm running: 
Nov 23 23:51:42 server xl2tpd[24594]: "/usr/sbin/pppd" 
Nov 23 23:51:42 server xl2tpd[24594]: "passive" 
Nov 23 23:51:42 server xl2tpd[24594]: "nodetach" 
Nov 23 23:51:42 server xl2tpd[24594]: "172.16.1.1:172.16.1.10" 
Nov 23 23:51:42 server xl2tpd[24594]: "auth" 
Nov 23 23:51:42 server xl2tpd[24594]: "name" 
Nov 23 23:51:42 server xl2tpd[24594]: "LinuxVPN" 
Nov 23 23:51:42 server xl2tpd[24594]: "file" 
Nov 23 23:51:42 server xl2tpd[24594]: "/etc/ppp/options.l2tpd.lns" 
Nov 23 23:51:42 server xl2tpd[24594]: "ipparam" 
Nov 23 23:51:42 server xl2tpd[24594]: "192.168.1.11" 
Nov 23 23:51:42 server xl2tpd[24594]: "/dev/pts/4" 
Nov 23 23:51:42 server xl2tpd[24594]: Call established with 192.168.1.11, Local: 62282, Remote: 63962, Serial: 419431530
Nov 23 23:51:42 server pppd[24725]: pppd 2.4.5 started by root, uid 0
Nov 23 23:51:42 server pppd[24725]: using channel 2
Nov 23 23:51:42 server NetworkManager[2577]: <warn> /sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring...
Nov 23 23:51:42 server pppd[24725]: Using interface ppp0
Nov 23 23:51:42 server pppd[24725]: Connect: ppp0 <--> /dev/pts/4
Nov 23 23:51:42 server pppd[24725]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <auth eap> <magic 0x77e23ebf> <pcomp> <accomp>]
Nov 23 23:51:42 server pppd[24725]: rcvd [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0x9efe7840> <pcomp> <accomp>]
Nov 23 23:51:42 server pppd[24725]: sent [LCP ConfAck id=0x1 <mru 1400> <asyncmap 0x0> <magic 0x9efe7840> <pcomp> <accomp>]
Nov 23 23:51:42 server pppd[24725]: rcvd [LCP ConfNak id=0x1 <auth chap MD5>]
Nov 23 23:51:42 server pppd[24725]: sent [LCP ConfReq id=0x2 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x77e23ebf> <pcomp> <accomp>]
Nov 23 23:51:42 server pppd[24725]: rcvd [LCP ConfAck id=0x2 <mru 1410> <asyncmap 0x0> <auth chap MD5> <magic 0x77e23ebf> <pcomp> <accomp>]
Nov 23 23:51:42 server pppd[24725]: sent [CHAP Challenge id=0x12 <34979b2e133837afc686efbdcaeeacd091>, name = "LinuxVPN"]
Nov 23 23:51:42 server pppd[24725]: rcvd [CHAP Response id=0x12 <d739f9e69fec1c6d3c5a5fb79117c6d9>, name = "USER"]
Nov 23 23:51:42 server pppd[24725]: sent [CHAP Success id=0x12 "Access granted"]
Nov 23 23:51:42 server pppd[24725]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 172.16.1.1>]
Nov 23 23:51:42 server pppd[24725]: rcvd [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Nov 23 23:51:42 server pppd[24725]: Unsupported protocol 'Compression Control Protocol' (0x80fd) received
Nov 23 23:51:42 server pppd[24725]: sent [LCP ProtRej id=0x3 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Nov 23 23:51:42 server pppd[24725]: 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>]
Nov 23 23:51:42 server pppd[24725]: sent [IPCP ConfRej id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Nov 23 23:51:42 server pppd[24725]: rcvd [IPCP ConfAck id=0x1 <compress VJ 0f 01> <addr 172.16.1.1>]
Nov 23 23:51:42 server pppd[24725]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f 01> <addr 0.0.0.0>]
Nov 23 23:51:42 server pppd[24725]: sent [IPCP ConfNak id=0x2 <addr 172.16.1.10>]
Nov 23 23:51:42 server pppd[24725]: rcvd [IPCP ConfReq id=0x3 <compress VJ 0f 01> <addr 172.16.1.10>]
Nov 23 23:51:42 server pppd[24725]: sent [IPCP ConfAck id=0x3 <compress VJ 0f 01> <addr 172.16.1.10>]
Nov 23 23:51:42 server pppd[24725]: Cannot determine ethernet address for proxy ARP
Nov 23 23:51:42 server pppd[24725]: local  IP address 172.16.1.1
Nov 23 23:51:42 server pppd[24725]: remote IP address 172.16.1.10
Nov 23 23:51:42 server pppd[24725]: Script /etc/ppp/ip-up started (pid 24727)
Nov 23 23:51:42 server pppd[24725]: Script /etc/ppp/ip-up finished (pid 24727), status = 0x0
Nov 23 23:51:53 server pppd[24725]: rcvd [LCP TermReq id=0x2 "User request"]
Nov 23 23:51:53 server pppd[24725]: LCP terminated by peer (User request)
Nov 23 23:51:53 server pppd[24725]: Connect time 0.2 minutes.
Nov 23 23:51:53 server pppd[24725]: Sent 0 bytes, received 388 bytes.
Nov 23 23:51:53 server pppd[24725]: Script /etc/ppp/ip-down started (pid 24732)
Nov 23 23:51:53 server pppd[24725]: sent [LCP TermAck id=0x2]
Nov 23 23:51:53 server pppd[24725]: Script /etc/ppp/ip-down finished (pid 24732), status = 0x0
Nov 23 23:51:53 server xl2tpd[24594]: result_code_avp: avp is incorrect size.  8 < 10
Nov 23 23:51:53 server xl2tpd[24594]: handle_avps: Bad exit status handling attribute 1 (Result Code) on mandatory packet.
Nov 23 23:51:53 server xl2tpd[24594]: Terminating pppd: sending TERM signal to pid 24725
Nov 23 23:51:53 server xl2tpd[24594]: Connection 14382 closed to 192.168.1.11, port 60782 (Result Code: expected at least 10, got 8)
Nov 23 23:51:53 server pppd[24725]: Terminating on signal 15
Nov 23 23:51:53 server pppd[24725]: Modem hangup
Nov 23 23:51:53 server pppd[24725]: Connection terminated.
Nov 23 23:51:53 server pppd[24725]: Exit.