[Openswan Users] VPN connection with IPSsec/L2TP drops after 10 minutes of idle time

beheer at topdesk.com beheer at topdesk.com
Thu Feb 19 12:28:10 EST 2009 

Hi,

I've set up a VPN connection using Openswan 2.4.6+dfsg.2-1.1 and xl2tpd 1.1.12.dfsg.1-1~bpo40+1 on Debian as VPN server and Windows XP SP3 as roadwarriors. 

Connection works like a charm, but if there is no network activity during 10 minutes, connection will drop. On the clients, I've set idle timeout to be 30 minutes, and on the server 3600 seconds. However, VPN will drop after aprox. 10 minutes. I attach logs from both Openswan and xl2tpd. Setting "idle" option in xl2tpd configuration to 2 minuytes makes no difference. Connection is dropped later.

I've seen some similar issues, but then the connection was dropping after 1 minute. In my case it works fine during a larger time. Any ideas on how to set a higher timeout? Who is breaking the connection? L2TP daemon? IPsec?

Thank you very much in advance!

Regards,

--
Xesc Arbona

/etc/ppp/options.l2tpd.lns:
ipcp-accept-local
ipcp-accept-remote
ms-dns 10.23.2.1
ms-wins 10.23.2.15
auth
crtscts
idle 3600
mtu 1200
mru 1200
nodefaultroute
debug
lock
proxyarp
connect-delay 5000
nologfd
require-mschap-v2

/etc/ipsec.d/roadwarrior.conf
conn roadwarrior-cert-net
        leftsubnet=10.23.0.0/22
        also=roadwarrior-cert

conn roadwarrior-cert-l2tp
        pfs=no
        rekey=no
        leftprotoport=17/1701
        rightprotoport=17/1701
        also=roadwarrior-cert

conn roadwarrior-cert
        authby=rsasig
        left=94.17.187.195
        leftsourceip=94.17.187.195
        leftnexthop=94.17.187.222
        leftcert=vpn.crt
        right=%any
        rightsubnet=vhost:%no,%priv
        auto=add

/var/log/auth.log:
Feb 19 17:51:19 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[351] 94.157.136.68 #3975: responding to Main Mode from unknown peer 94.157.136.68
Feb 19 17:51:19 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[351] 94.157.136.68 #3975: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Feb 19 17:51:19 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[351] 94.157.136.68 #3975: STATE_MAIN_R1: sent MR1, expecting MI2
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[351] 94.157.136.68 #3975: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike-02/03: peer is NATed
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[351] 94.157.136.68 #3975: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[351] 94.157.136.68 #3975: STATE_MAIN_R2: sent MR2, expecting MI3
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[351] 94.157.136.68 #3975: Main mode peer ID is ID_DER_ASN1_DN: 'CN=LAP1144.tis.local'
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[351] 94.157.136.68 #3975: switched from "roadwarrior-cert-net" to "roadwarrior-cert-net"
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[352] 94.157.136.68 #3975: deleting connection "roadwarrior-cert-net" instance with peer 94.157.136.68 {isakmp=#0/ipsec=#0}
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[352] 94.157.136.68 #3975: I am sending my cert
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[352] 94.157.136.68 #3975: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[352] 94.157.136.68 #3975: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_RSA_SIG cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp2048}
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-l2tp"[169] 94.157.136.68 #3976: responding to Quick Mode {msgid:951666e7}
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-l2tp"[169] 94.157.136.68 #3976: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Feb 19 17:51:20 VM-fw1 pluto[3149]: "roadwarrior-cert-l2tp"[169] 94.157.136.68 #3976: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
Feb 19 17:51:21 VM-fw1 pluto[3149]: "roadwarrior-cert-l2tp"[169] 94.157.136.68 #3976: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Feb 19 17:51:21 VM-fw1 pluto[3149]: "roadwarrior-cert-l2tp"[169] 94.157.136.68 #3976: STATE_QUICK_R2: IPsec SA established {ESP=>0xb2010c99 <0xb6d8655f xfrm=3DES_0-HMAC_MD5 NATD=94.157.136.68:4500 DPD=none}
Feb 19 18:02:29 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[352] 94.157.136.68 #3975: received Delete SA(0xb2010c99) payload: deleting IPSEC State #3976
Feb 19 18:02:29 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[352] 94.157.136.68 #3975: deleting connection "roadwarrior-cert-l2tp" instance with peer 94.157.136.68 {isakmp=#0/ipsec=#0}
Feb 19 18:02:29 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[352] 94.157.136.68 #3975: received and ignored informational message
Feb 19 18:02:29 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[352] 94.157.136.68 #3975: received Delete SA payload: deleting ISAKMP State #3975
Feb 19 18:02:29 VM-fw1 pluto[3149]: "roadwarrior-cert-net"[352] 94.157.136.68: deleting connection "roadwarrior-cert-net" instance with peer 94.157.136.68 {isakmp=#0/ipsec=#0}


/var/log/syslog:
Feb 19 17:51:21 VM-fw1 xl2tpd[24204]: handle_avps: handling avp's for tunnel 46773, call 0
Feb 19 17:51:21 VM-fw1 xl2tpd[24204]: message_type_avp: message type 1 (Start-Control-Connection-Request)
Feb 19 17:51:21 VM-fw1 xl2tpd[24204]: protocol_version_avp: peer is using version 1, revision 0.
Feb 19 17:51:21 VM-fw1 xl2tpd[24204]: framing_caps_avp: supported peer frames: sync
Feb 19 17:51:21 VM-fw1 xl2tpd[24204]: bearer_caps_avp: supported peer bearers:
Feb 19 17:51:21 VM-fw1 xl2tpd[24204]: firmware_rev_avp: peer reports firmware version 1280 (0x0500)
Feb 19 17:51:21 VM-fw1 xl2tpd[24204]: hostname_avp: peer reports hostname 'Roadwarrior-TEST'
Feb 19 17:51:21 VM-fw1 xl2tpd[24204]: vendor_avp: peer reports vendor 'Microsoft'
Feb 19 17:51:21 VM-fw1 xl2tpd[24204]: assigned_tunnel_avp: using peer's tunnel 9
Feb 19 17:51:21 VM-fw1 xl2tpd[24204]: receive_window_size_avp: peer wants RWS of 8.  Will use flow control.
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: handle_avps: handling avp's for tunnel 26896, call 0
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: message_type_avp: message type 1 (Start-Control-Connection-Request)
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: protocol_version_avp: peer is using version 1, revision 0.
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: framing_caps_avp: supported peer frames: sync
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: bearer_caps_avp: supported peer bearers:
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: firmware_rev_avp: peer reports firmware version 1280 (0x0500)
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: hostname_avp: peer reports hostname 'Roadwarrior-TEST'
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: vendor_avp: peer reports vendor 'Microsoft'
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: assigned_tunnel_avp: using peer's tunnel 9
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: receive_window_size_avp: peer wants RWS of 8.  Will use flow control.
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: control_finish: Peer requested tunnel 9 twice, ignoring second one.
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: handle_avps: handling avp's for tunnel 46773, call 0
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: message_type_avp: message type 3 (Start-Control-Connection-Connected)
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: Connection established to 94.157.136.68, 1701.  Local: 46773, Remote: 9 (ref=0/0).  LNS session is 'default'
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: handle_avps: handling avp's for tunnel 46773, call 0
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: message_type_avp: message type 10 (Incoming-Call-Request)
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: message_type_avp: new incoming call
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: assigned_call_avp: using peer's call 1
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: call_serno_avp: serial number is 0
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: bearer_type_avp: peer bears: analog
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: handle_avps: handling avp's for tunnel 46773, call 27158
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: message_type_avp: message type 12 (Incoming-Call-Connected)
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: tx_speed_avp: transmit baud rate is 10000000
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: frame_type_avp: peer uses:sync frames
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: ignore_avp : Ignoring AVP
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: start_pppd: I'm running:
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "/usr/sbin/pppd"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "passive"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "-detach"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "10.23.2.1:10.23.2.21"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "refuse-pap"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "auth"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "require-chap"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "name"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "VPNSAAS"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "debug"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "file"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "/etc/ppp/options.l2tpd.lns"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: "/dev/pts/3"
Feb 19 17:51:23 VM-fw1 xl2tpd[24204]: Call established with 94.157.136.68, Local: 27158, Remote: 1, Serial: 0
[...]
Feb 19 18:02:28 VM-fw1 xl2tpd[24204]: Maximum retries exceeded for tunnel 46773.  Closing.
Feb 19 18:02:28 VM-fw1 xl2tpd[24204]: Untrustingly terminating pppd: sending KILL signal to pid 24564
Feb 19 18:02:28 VM-fw1 xl2tpd[24204]: pppd 24564 successfully terminated
Feb 19 18:02:28 VM-fw1 xl2tpd[24204]: Connection 9 closed to 94.157.136.68, port 1701 (Timeout)
Feb 19 18:02:29 VM-fw1 xl2tpd[24204]: Can not find tunnel 46773 (refhim=0)
Feb 19 18:02:29 VM-fw1 xl2tpd[24204]: network_thread: unable to find call or tunnel to handle packet.  call = 0, tunnel = 46773 Dumping.
Feb 19 18:02:29 VM-fw1 xl2tpd[24204]: Can not find tunnel 46773 (refhim=0)
Feb 19 18:02:29 VM-fw1 xl2tpd[24204]: network_thread: unable to find call or tunnel to handle packet.  call = 0, tunnel = 46773 Dumping.
Feb 19 18:02:29 VM-fw1 xl2tpd[24204]: Can not find tunnel 46773 (refhim=0)
Feb 19 18:02:29 VM-fw1 xl2tpd[24204]: network_thread: unable to find call or tunnel to handle packet.  call = 27158, tunnel = 46773 Dumping.
Feb 19 18:02:29 VM-fw1 xl2tpd[24204]: Can not find tunnel 46773 (refhim=0)
Feb 19 18:02:29 VM-fw1 xl2tpd[24204]: network_thread: unable to find call or tunnel to handle packet.  call = 0, tunnel = 46773 Dumping.

More information about the Users mailing list