[Openswan Users] random l2tp/pppd failure

Ben Willmore bwillmore at berkeley.edu
Sat Feb 18 13:56:31 CET 2006 

I now have a successful ipsec/l2tp/ppp setup, which works 2/3 of the
time but has one annoying problem: seemingly randomly, l2tpd fails to
kill pppd when the client disconnects.  When this happens, it wedges
the whole system for all users -- existing connections freeze and new
ones can't be established.

My claim that it's random comes from multiple reconnects/disconnects
from the same client.  It will work about 2/3 of the time with no
problems.  On the remaining 1/3, when the client disconnects, the pppd
process remains behind, wedging l2tpd etc.

Thanks again for any insight into what's making it flaky.

Ben

Here is a sample log from a failed connect/disconnect cycle:
Feb 18 12:15:01 lithium l2tpd[19210]: ourtid = 31427, entropy_buf = 7ac3
Feb 18 12:15:01 lithium l2tpd[19210]: ourcid = 33679, entropy_buf = 838f
Feb 18 12:15:01 lithium l2tpd[19210]: check_control: control, cid = 0,
Ns = 0, Nr = 0
Feb 18 12:15:01 lithium l2tpd[19210]: handle_avps: handling avp's for
tunnel 31427, call 33679
Feb 18 12:15:01 lithium l2tpd[19210]: message_type_avp: message type 1
(Start-Control-Connection-Request)
Feb 18 12:15:01 lithium l2tpd[19210]: protocol_version_avp: peer is
using version 1, revision 0.
Feb 18 12:15:01 lithium l2tpd[19210]: framing_caps_avp: supported peer
frames:async sync
Feb 18 12:15:01 lithium l2tpd[19210]: hostname_avp: peer reports hostname ''
Feb 18 12:15:01 lithium l2tpd[19210]: assigned_tunnel_avp: using
peer's tunnel 102
Feb 18 12:15:01 lithium l2tpd[19210]: receive_window_size_avp: peer
wants RWS of 4.  Will use flow control.
Feb 18 12:15:01 lithium l2tpd[19210]: check_control: control, cid = 0,
Ns = 1, Nr = 1
Feb 18 12:15:01 lithium l2tpd[19210]: handle_avps: handling avp's for
tunnel 31427, call 33679
Feb 18 12:15:01 lithium l2tpd[19210]: message_type_avp: message type 3
(Start-Control-Connection-Connected)
Feb 18 12:15:01 lithium l2tpd[19210]: control_finish: Connection
established to xx.xx.xx.xx, 50902.  Local: 31427, Remote: 102.  LNS
session is 'default'
Feb 18 12:15:01 lithium l2tpd[19210]: check_control: control, cid = 0,
Ns = 2, Nr = 1
Feb 18 12:15:01 lithium l2tpd[19210]: handle_avps: handling avp's for
tunnel 31427, call 33679
Feb 18 12:15:01 lithium l2tpd[19210]: message_type_avp: message type
10 (Incoming-Call-Request)
Feb 18 12:15:01 lithium l2tpd[19210]: message_type_avp: new incoming call
Feb 18 12:15:01 lithium l2tpd[19210]: ourcid = 45349, entropy_buf = b125
Feb 18 12:15:01 lithium l2tpd[19210]: assigned_session_avp: assigned
session id: 4736
Feb 18 12:15:01 lithium l2tpd[19210]: call_serno_avp: serial number is 1
Feb 18 12:15:01 lithium l2tpd[19210]: check_control: control, cid =
4736, Ns = 3, Nr = 2
Feb 18 12:15:01 lithium l2tpd[19210]: handle_avps: handling avp's for
tunnel 31427, call 45349
Feb 18 12:15:01 lithium l2tpd[19210]: message_type_avp: message type
12 (Incoming-Call-Connected)
Feb 18 12:15:01 lithium l2tpd[19210]: tx_speed_avp: transmit baud rate
is 1000000
Feb 18 12:15:01 lithium l2tpd[19210]: frame_type_avp: peer uses:async frames
Feb 18 12:15:01 lithium l2tpd[19210]: start_pppd: I'm running:
Feb 18 12:15:01 lithium l2tpd[19210]: "/usr/sbin/pppd"
Feb 18 12:15:01 lithium l2tpd[19210]: "passive"
Feb 18 12:15:01 lithium l2tpd[19210]: "-detach"
Feb 18 12:15:01 lithium l2tpd[19210]: "192.168.2.203:192.168.2.204"
Feb 18 12:15:01 lithium l2tpd[19210]: "refuse-pap"
Feb 18 12:15:01 lithium l2tpd[19210]: "auth"
Feb 18 12:15:01 lithium l2tpd[19210]: "require-chap"
Feb 18 12:15:01 lithium l2tpd[19210]: "name"
Feb 18 12:15:01 lithium l2tpd[19210]: "Test"
Feb 18 12:15:01 lithium l2tpd[19210]: "debug"
Feb 18 12:15:01 lithium l2tpd[19210]: "file"
Feb 18 12:15:01 lithium l2tpd[19210]: "/etc/ppp/options.l2tpd"
Feb 18 12:15:01 lithium l2tpd[19210]: "/dev/ttyp0"
Feb 18 12:15:01 lithium l2tpd[19210]:
Feb 18 12:15:01 lithium pppd[17661]: pppd options in effect:
Feb 18 12:15:01 lithium l2tpd[19210]: control_finish: Call established
with xx.xx.xx.xx, Local: 45349, Remote: 4736, Serial: 1
Feb 18 12:15:01 lithium pppd[17661]: debug debug^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: -detach^I^I# (from command line)
Feb 18 12:15:01 lithium pppd[17661]: idle 1800^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: nologfd^I^I# (from /etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: connect-delay 5000^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: dump^I^I# (from /etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: auth^I^I# (from /etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: refuse-pap^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: refuse-chap^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: refuse-mschap^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: name hostname^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: /dev/ttyp0^I^I# (from command line)
Feb 18 12:15:01 lithium pppd[17661]: lock^I^I# (from /etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: crtscts^I^I# (from /etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: modem^I^I# (from /etc/ppp/options)
Feb 18 12:15:01 lithium pppd[17661]: asyncmap 0^I^I# (from /etc/ppp/options)
Feb 18 12:15:01 lithium pppd[17661]: mru 1400^I^I# (from /etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: mtu 1400^I^I# (from /etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: passive^I^I# (from command line)
Feb 18 12:15:01 lithium pppd[17661]: lcp-echo-failure 1^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: lcp-echo-interval 2^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: hide-password^I^I# (from /etc/ppp/options)
Feb 18 12:15:01 lithium pppd[17661]: ms-dns xxx # [don't know how to
print value]^I^I# (from /etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: proxyarp^I^I# (from /etc/ppp/options)
Feb 18 12:15:01 lithium pppd[17661]: netmask 255.255.255.0^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: 192.168.2.203:192.168.2.204^I^I#
(from command line)
Feb 18 12:15:01 lithium pppd[17661]: nobsdcomp^I^I# (from
/etc/ppp/options.l2tpd)
Feb 18 12:15:01 lithium pppd[17661]: noipx^I^I# (from /etc/ppp/options)
Feb 18 12:15:01 lithium pppd[17661]: pppd 2.4.2 started by root, uid 0
Feb 18 12:15:01 lithium pppd[17661]: using channel 86
Feb 18 12:15:01 lithium pppd[17661]: Using interface ppp0
Feb 18 12:15:01 lithium pppd[17661]: Connect: ppp0 <--> /dev/ttyp0
Feb 18 12:15:01 lithium pppd[17661]: sent [LCP ConfReq id=0x1 <mru
1400> <asyncmap 0x0> <auth chap MD5> <magic 0xf0ca4731> <pcomp>
<accomp>]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x7b4b2e1a> <pcomp> <accomp>]
Feb 18 12:15:01 lithium pppd[17661]: sent [LCP ConfAck id=0x1
<asyncmap 0x0> <magic 0x7b4b2e1a> <pcomp> <accomp>]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [LCP ConfAck id=0x1 <mru
1400> <asyncmap 0x0> <auth chap MD5> <magic 0xf0ca4731> <pcomp>
<accomp>]
Feb 18 12:15:01 lithium pppd[17661]: sent [LCP EchoReq id=0x0 magic=0xf0ca4731]
Feb 18 12:15:01 lithium pppd[17661]: sent [CHAP Challenge id=0xaa
<d52bdf0bf3f1e41052fb3f5df005e4fa69>, name = "hostname"]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [LCP EchoReq id=0x0 magic=0x7b4b2e1a]
Feb 18 12:15:01 lithium pppd[17661]: sent [LCP EchoRep id=0x0 magic=0xf0ca4731]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [LCP EchoRep id=0x0 magic=0x7b4b2e1a]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [CHAP Response id=0xaa
<f368a8803b72e0756a7d8bc6b8d8106d>, name = "xxxxxxx"]
Feb 18 12:15:01 lithium pppd[17661]: sent [CHAP Success id=0xaa
"Access granted"]
Feb 18 12:15:01 lithium pppd[17661]: sent [CCP ConfReq id=0x1 <deflate
15> <deflate(old#) 15>]
Feb 18 12:15:01 lithium pppd[17661]: sent [IPCP ConfReq id=0x1
<compress VJ 0f 01> <addr 192.168.2.203>]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [IPCP ConfReq id=0x1 <addr
0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Feb 18 12:15:01 lithium pppd[17661]: sent [IPCP ConfNak id=0x1 <addr
192.168.2.204> <ms-dns1 192.168.2.101> <ms-dns3 128.32.136.9>]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [IPV6CP ConfReq id=0x1 <addr
fe80::020d:93ff:fe56:5742>]
Feb 18 12:15:01 lithium pppd[17661]: Unsupported protocol 0x8057 received
Feb 18 12:15:01 lithium pppd[17661]: sent [LCP ProtRej id=0x2 80 57 01
01 00 0e 01 0a 02 0d 93 ff fe 56 57 42]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [proto=0x8235] 01 01 00 10
01 06 00 00 00 01 02 06 00 00 00 01
Feb 18 12:15:01 lithium pppd[17661]: Unsupported protocol 0x8235 received
Feb 18 12:15:01 lithium pppd[17661]: sent [LCP ProtRej id=0x3 82 35 01
01 00 10 01 06 00 00 00 01 02 06 00 00 00 01]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [LCP ProtRej id=0x2 80 fd 01
01 00 0c 1a 04 78 00 18 04 78 00]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [IPCP ConfRej id=0x1
<compress VJ 0f 01>]
Feb 18 12:15:01 lithium pppd[17661]: sent [IPCP ConfReq id=0x2 <addr
192.168.2.203>]
Feb 18 12:15:01 lithium pppd[17661]: rcvd [IPCP ConfReq id=0x2 <addr
192.168.2.204> <ms-dns1 192.168.2.101> <ms-dns3 128.32.136.9>]
Feb 18 12:15:01 lithium pppd[17661]: sent [IPCP ConfAck id=0x2 <addr
192.168.2.204> <ms-dns1 192.168.2.101> <ms-dns3 128.32.136.9>]
Feb 18 12:15:02 lithium pppd[17661]: rcvd [IPCP ConfAck id=0x2 <addr
192.168.2.203>]
Feb 18 12:15:02 lithium pppd[17661]: found interface eth0 for proxy arp
Feb 18 12:15:02 lithium pppd[17661]: local  IP address 192.168.2.203
Feb 18 12:15:02 lithium pppd[17661]: remote IP address 192.168.2.204
Feb 18 12:15:02 lithium pppd[17661]: Script /etc/ppp/ip-up started (pid 17672)
Feb 18 12:15:02 lithium postfix/master[27671]: reload configuration
Feb 18 12:15:02 lithium pppd[17661]: Script /etc/ppp/ip-up finished
(pid 17672), status = 0x0
Feb 18 12:15:03 lithium pppd[17661]: sent [LCP EchoReq id=0x1 magic=0xf0ca4731]
Feb 18 12:15:03 lithium pppd[17661]: rcvd [LCP EchoRep id=0x1 magic=0x7b4b2e1a]
...
Feb 18 12:15:29 lithium pppd[17661]: sent [LCP EchoReq id=0xe magic=0xf0ca4731]
Feb 18 12:15:30 lithium pppd[17661]: rcvd [LCP TermReq id=0x3 "User request"]
Feb 18 12:15:30 lithium pppd[17661]: LCP terminated by peer (User request)
Feb 18 12:15:30 lithium pppd[17661]: Connect time 0.5 minutes.
Feb 18 12:15:30 lithium pppd[17661]: Sent 837277 bytes, received 19586 bytes.
Feb 18 12:15:30 lithium pppd[17661]: Script /etc/ppp/ip-down started (pid 17821)
Feb 18 12:15:30 lithium pppd[17661]: sent [LCP TermAck id=0x3]
Feb 18 12:15:30 lithium postfix/master[27671]: reload configuration
Feb 18 12:15:30 lithium pppd[17661]: Script /etc/ppp/ip-down finished
(pid 17821), status = 0x0
Feb 18 12:15:30 lithium l2tpd[19210]: check_control: control, cid =
4736, Ns = 4, Nr = 2
Feb 18 12:15:30 lithium l2tpd[19210]: handle_avps: handling avp's for
tunnel 31427, call 45349
Feb 18 12:15:30 lithium l2tpd[19210]: message_type_avp: message type
14 (Call-Disconnect-Notify)
Feb 18 12:15:30 lithium l2tpd[19210]: assigned_session_avp: assigned
session id: 4736
Feb 18 12:15:30 lithium l2tpd[19210]: result_code_avp: peer closing
for reason 3 (Call disconnected for administrative reasons), error = 0
()
Feb 18 12:15:30 lithium l2tpd[19210]: control_finish: Peer tried to
disconnect without specifying call ID
Feb 18 12:15:30 lithium l2tpd[19210]: check_control: control, cid = 0,
Ns = 5, Nr = 2
Feb 18 12:15:30 lithium l2tpd[19210]: handle_avps: handling avp's for
tunnel 31427, call 33679
Feb 18 12:15:30 lithium l2tpd[19210]: message_type_avp: message type 4
(Stop-Control-Connection-Notification)
Feb 18 12:15:30 lithium l2tpd[19210]: assigned_tunnel_avp: using
peer's tunnel 102
Feb 18 12:15:30 lithium l2tpd[19210]: result_code_avp: peer closing
for reason 1 (General request to clear control connection), error = 0
()
Feb 18 12:15:30 lithium l2tpd[19210]: control_finish: Connection
closed to xx.xx.xx.xx, port 50902 (), Local: 31427, Remote: 102

The log for a successful run is identical except for, at the end:

Feb 18 12:17:12 lithium pppd[18316]: Terminating on signal 15.
Feb 18 12:17:12 lithium pppd[18316]: Modem hangup
Feb 18 12:17:12 lithium pppd[18316]: Connection terminated.
Feb 18 12:17:12 lithium pppd[18316]: Exit.

My config files:
---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"
        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,%v4:!
192.168.2.0/24

conn L2TP-PSK
  type=transport
  authby=secret
  pfs=no
  rekey=no
  keyingtries=3
  left=192.168.2.9
  leftnexthop=192.168.2.1
  leftprotoport=17/1701
  right=%any
  rightsubnet=vhost:%no,%priv
  rightprotoport=17/%any
  auto=add

---l2tpd.conf
[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 = LinuxVPNserver
ppp debug = yes
pppoptfile = /etc/ppp/options.l2tpd
length bit = yes

---options.l2tpd
debug
dump

crtscts
mtu 1400
mru 1400

connect-delay 5000

# authentication
auth
name hostname
refuse-pap
refuse-chap
refuse-mschap
require-mschap-v2

# network setup
ms-dns 192.168.2.101
ms-dns 128.32.136.9
netmask 255.255.255.0
#proxyarp

# err
lock
nobsdcomp

More information about the Users mailing list