Your message dated Sat, 20 Oct 2007 09:26:12 -0400
with message-id <[EMAIL PROTECTED]>
and subject line Closing bug about l2tpd ppp kill failure on disconnect
has caused the attached Bug report to be marked as done.
This means that you claim that the problem has been dealt with.
If this is not the case it is now your responsibility to reopen the
Bug report if necessary, and/or fix the problem forthwith.
(NB: If you are a system administrator and have no idea what I am
talking about this indicates a serious mail system misconfiguration
somewhere. Please contact me immediately.)
Debian bug tracking system administrator
(administrator, Debian Bugs database)
--- Begin Message ---
Package: l2tpd
Version: 0.70-pre20031121
When this happens, it wedges the whole l2tpd system for all users --
existing connections freeze and new ones can't be established. This
makes l2tpd unusable because when one user experiences the random
fault, all users are affected, and the ipsec/l2tp daemons have to be
restarted.
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.
I applied the patches here (most have already been applied or don't
apply any more), and it apears to have fixed the problem:
http://www.jacco2.dds.nl/networking/tarballs/l2tpd-10jdl.tgz
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.
Ben
--- End Message ---
--- Begin Message ---
As I have not heard anything, I am closing this bug.
Regards,
-Roberto
--
Roberto C. Sánchez
http://people.connexer.com/~roberto
http://www.connexer.com
signature.asc
Description: Digital signature
--- End Message ---
