A simple debugging technique I have used (short of mangling the source) is to run programs with strace. Redirect the copious system call trace log from stderr to a file and least you might get an idea of what pppd was last trying to do before it died.
Martin Visser Technology Consultant Consulting & Integration Technology Solutions Group - HP Services 410 Concord Road Rhodes NSW 2138 Australia Mobile: +61-411-254-513 Fax: +61-2-9022-1800 E-mail: martin.visserAThp.com This email (including any attachments) is intended only for the use of the individual or entity named above and may contain information that is confidential, proprietary or privileged. If you are not the intended recipient, please notify HP immediately by return email and then delete the email, destroy any printed copy and do not disclose or use the information in it. -----Original Message----- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Howard Lowndes Sent: Tuesday, 27 June 2006 4:44 PM Cc: [email protected] Subject: Re: [SLUG] L2TPD/IPSec problems - getting there but not quite I have pretty much established that the problem does not lie with rp-l2tpd (vanilla l2tpd is another thing altogether and doesn't even get this far), but with the pppd daemon itself. Using some scripting in the /etc/ppp/auth-up, /etc/ppp/ip-up and /etc/ppp/ip-down scripts, I can see that the Winbox is being authenticated OK otherwise /etc/ppp/auth-up would not run at all - according to man pppd. That is confirmed by the pppd syslog messages. What I did with the /etc/ppp/ip-up script is to look at ps to see what the status of pppd was before it dies, and I have the following (slightly formatted), using: ps axw | grep -e ppp -e pty 17491 ? S 0:00 pppd sync nodetach noaccomp nobsdcomp nodeflate nopcomp novj novjccomp nodetach proxyarp require-chap 192.168.129.1:192.168.129.45 unit 1 local ms-dns 192.168.128.17 ms-dns 218.214.47.111 ms-wins 192.168.129.126 lcp-echo-interval 10 lcp-echo-failure 5 debug kdebug 1 17496 ? Ss 0:00 /bin/bash /etc/ppp/ip-up ppp1 /dev/pts/1 38400 192.168.129.1 192.168.129.45 17498 ? R 0:00 /bin/sh /etc/ppp/ip-up.local ppp1 /dev/pts/1 38400 192.168.129.1 192.168.129.45 17504 ? R 0:00 /bin/sh /etc/ppp/ip-up.local ppp1 /dev/pts/1 38400 192.168.129.1 192.168.129.45 So, it looks like pppd is getting started and none of the above looks out of order, but that doesn't explain why it immediately dies again. Needless to say there is no indication in the syslogs as to why it is dying, so I can only assume that it is planned death and not an erroneous death. This really is getting frustrating, and what's worse, it doesn't look as if it's M$ fault either... Howard Lowndes wrote: > On Mon, June 26, 2006 17:05, tone wrote: >> Ah, yes, I see, you have ditched IPSec :) >> >> So, from what I recall of PPPD devilery, it looks like IPCP message 0x2 >> is not being responded to, which is what causes the LCP session to be >> killed as the "No network protocols running" refers to the IPCP >> handshake failing.. IPCP is the IP Control Protocol, so it's your layer >> 3 or network layer being established over the PPP link ;) >> >> What does the "lns" and "lac" configs refer to? Back in debian potato >> there was only one pppd options file so I'm not sure why you have 2 >> listed? Things have moved on it seems ;) > > LAC stands for L2TP Access Concentrator, and LNS stands for L2TP Network > Server. My understanding is that the LAC is a handler for the Windows > peer. > >> But anyway, the message not being responded to is your local IP address >> (192.168.129.1), I would change this to 0.0.0.0 or leave it out >> completely (not sure if leaving it out works or not - it's been a >> while :) > > OK, I might try that. > >> You should probably have ipcp-accept-local in both options files as >> well, and it wouldn't hurt to setup ms-dns as the ConfReq from the >> client is setting these as 0.0.0.0 > > Valid points. > >> Also, you should probably just have the local and remote IP addresses as >> 0.0.0.0, (so the line should be 0.0.0.0:0.0.0.0 instead of >> 192.168.129.1:192.168.129.45), and then in /etc/ppp/chap-secrets have >> >> username * password 192.168.129.45 >> >> as this will then allow you to set the IP address on a per login basis >> >> hope that helps >> >> >> tone. >> >> >> >> >> On Mon, 2006-06-26 at 10:16 +1000, Howard Lowndes wrote: >>> I have made some progress on this problem. >>> >>> I have ditched l2tpd as distributed with FC and have compiled up the >>> rp-l2tp project instead. >>> >>> This has give me some success because IPSec is now being correctly >>> established and, using the pppd debug facility, I can see pppd starting >>> up >>> and I can see the LCP, IPCP and CHAP negotiations happening. My problem >>> now is that the pppd session starts and then appears to immediately die; >>> I >>> am assuming this by reason of /etc/ppp/ip-up running and then being >>> immediately followed 2 seconds later by /etc/ppp/ip-down running. I can >>> also see, again from the log, the EchoReq going out and the EchoRep back >>> , >>> but after the ip-up/down, there is no corresponding EchoRep to each 10 >>> second EchoReq. >>> >>> What sort of setting should I be looking at to make pppd stay up >>> (Cyberviagra ?) >>> >>> Logs and pppd options follow: >>> >>> Jun 26 09:50:24 acay pppd[2798]: pppd 2.4.2 started by root, uid 0 >>> Jun 26 09:50:24 acay pppd[2798]: speed 31 not supported >>> Jun 26 09:50:24 acay pppd[2798]: using channel 4 >>> Jun 26 09:50:24 acay pppd[2798]: Using interface ppp0 >>> Jun 26 09:50:24 acay pppd[2798]: Connect: ppp0 <--> /dev/pts/1 >>> Jun 26 09:50:24 acay pppd[2798]: sent [LCP ConfReq id=0x1 <mru 1420> >>> <asyncmap 0x0> <auth chap MD5> <magic 0x79d624bc>] >>> Jun 26 09:50:25 acay pppd[2798]: rcvd [LCP ConfReq id=0x0 <mru 1400> >>> <magic 0x5e3e6db1> <pcomp> <accomp>] >>> Jun 26 09:50:25 acay pppd[2798]: sent [LCP ConfRej id=0x0 <pcomp> >>> <accomp>] >>> Jun 26 09:50:25 acay pppd[2798]: rcvd [LCP ConfAck id=0x1 <mru 1420> >>> <asyncmap 0x0> <auth chap MD5> <magic 0x79d624bc>] >>> Jun 26 09:50:25 acay pppd[2798]: rcvd [LCP ConfReq id=0x1 <mru 1400> >>> <magic 0x5e3e6db1>] >>> Jun 26 09:50:25 acay pppd[2798]: sent [LCP ConfAck id=0x1 <mru 1400> >>> <magic 0x5e3e6db1>] >>> Jun 26 09:50:25 acay pppd[2798]: sent [LCP EchoReq id=0x0 >>> magic=0x79d624bc] >>> Jun 26 09:50:25 acay pppd[2798]: sent [CHAP Challenge id=0x73 >>> <175dbe1f825440a5a9b8d2cf626ca27c73d86e7758>, name = >>> "acay.mydomain.tld"] >>> Jun 26 09:50:25 acay pppd[2798]: rcvd [LCP EchoRep id=0x0 >>> magic=0x5e3e6db1] >>> Jun 26 09:50:25 acay pppd[2798]: rcvd [CHAP Response id=0x73 >>> <4d48975323d500433c9146016c63ee9e>, name = "ClientID"] >>> Jun 26 09:50:25 acay pppd[2798]: sent [CHAP Success id=0x73 "Access >>> granted"] >>> Jun 26 09:50:25 acay pppd[2798]: sent [IPCP ConfReq id=0x1 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:25 acay pppd[2798]: rcvd [IPCP ConfReq id=0x2 <addr >>> 0.0.0.0> >>> <ms-dns1 0.0.0.0> <ms-wins 0.0.0.0> <ms-dns3 0.0.0.0> <ms-wins 0.0.0.0>] >>> Jun 26 09:50:25 acay pppd[2798]: sent [IPCP ConfRej id=0x2 <ms-dns1 >>> 0.0.0.0> <ms-wins 0.0.0.0> <ms-dns3 0.0.0.0> <ms-wins 0.0.0.0>] >>> Jun 26 09:50:25 acay pppd[2798]: rcvd [IPCP ConfAck id=0x1 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:25 acay pppd[2798]: rcvd [IPCP ConfReq id=0x3 <addr >>> 0.0.0.0>] >>> Jun 26 09:50:25 acay pppd[2798]: sent [IPCP ConfNak id=0x3 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:26 acay pppd[2798]: rcvd [IPCP ConfReq id=0x4 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:26 acay pppd[2798]: sent [IPCP ConfAck id=0x4 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:26 acay pppd[2798]: local IP address 192.168.129.1 >>> Jun 26 09:50:26 acay pppd[2798]: remote IP address 192.168.129.45 >>> Jun 26 09:50:26 acay pppd[2798]: Script /etc/ppp/ip-up started (pid >>> 2803) >>> Jun 26 09:50:26 acay pppd[2798]: Script /etc/ppp/ip-up finished (pid >>> 2803), status = 0x0 >>> Jun 26 09:50:27 acay pppd[2798]: rcvd [IPCP ConfReq id=0x5 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:28 acay pppd[2798]: Script /etc/ppp/ip-down started (pid >>> 2805) >>> Jun 26 09:50:28 acay pppd[2798]: sent [IPCP ConfReq id=0x2 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:28 acay pppd[2798]: sent [IPCP ConfAck id=0x5 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:28 acay pppd[2798]: Script /etc/ppp/ip-down finished (pid >>> 2805), status = 0x0 >>> Jun 26 09:50:30 acay pppd[2798]: rcvd [IPCP ConfReq id=0x6 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:30 acay pppd[2798]: sent [IPCP ConfAck id=0x6 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:31 acay pppd[2798]: sent [IPCP ConfReq id=0x2 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:34 acay pppd[2798]: sent [IPCP ConfReq id=0x2 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:34 acay pppd[2798]: rcvd [IPCP ConfReq id=0x7 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:34 acay pppd[2798]: sent [IPCP ConfAck id=0x7 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:35 acay pppd[2798]: sent [LCP EchoReq id=0x1 >>> magic=0x79d624bc] >>> Jun 26 09:50:37 acay pppd[2798]: sent [IPCP ConfReq id=0x2 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:38 acay pppd[2798]: rcvd [IPCP ConfReq id=0x8 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:38 acay pppd[2798]: sent [IPCP ConfAck id=0x8 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:40 acay pppd[2798]: sent [IPCP ConfReq id=0x2 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:42 acay pppd[2798]: rcvd [IPCP ConfReq id=0x9 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:42 acay pppd[2798]: sent [IPCP ConfAck id=0x9 <addr >>> 192.168.129.45>] >>> Jun 26 09:50:43 acay pppd[2798]: sent [IPCP ConfReq id=0x2 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:45 acay pppd[2798]: sent [LCP EchoReq id=0x2 >>> magic=0x79d624bc] >>> Jun 26 09:50:46 acay pppd[2798]: sent [IPCP ConfReq id=0x2 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:46 acay pppd[2798]: rcvd [IPCP ConfReq id=0xa <addr >>> 192.168.129.45>] >>> Jun 26 09:50:46 acay pppd[2798]: sent [IPCP ConfAck id=0xa <addr >>> 192.168.129.45>] >>> Jun 26 09:50:49 acay pppd[2798]: sent [IPCP ConfReq id=0x2 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:50 acay pppd[2798]: rcvd [IPCP ConfReq id=0xb <addr >>> 192.168.129.45>] >>> Jun 26 09:50:50 acay pppd[2798]: sent [IPCP ConfAck id=0xb <addr >>> 192.168.129.45>] >>> Jun 26 09:50:52 acay pppd[2798]: sent [IPCP ConfReq id=0x2 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:54 acay pppd[2798]: rcvd [IPCP ConfReq id=0xc <addr >>> 192.168.129.45>] >>> Jun 26 09:50:54 acay pppd[2798]: sent [IPCP ConfAck id=0xc <addr >>> 192.168.129.45>] >>> Jun 26 09:50:55 acay pppd[2798]: sent [IPCP ConfReq id=0x2 <addr >>> 192.168.129.1>] >>> Jun 26 09:50:55 acay pppd[2798]: sent [LCP EchoReq id=0x3 >>> magic=0x79d624bc] >>> Jun 26 09:50:58 acay pppd[2798]: IPCP: timeout sending Config-Requests >>> Jun 26 09:50:58 acay pppd[2798]: sent [LCP TermReq id=0x2 "No network >>> protocols running"] >>> Jun 26 09:50:59 acay pppd[2798]: rcvd [IPCP ConfReq id=0xd <addr >>> 192.168.129.45>] >>> Jun 26 09:50:59 acay pppd[2798]: Discarded non-LCP packet when LCP not >>> open >>> Jun 26 09:51:01 acay pppd[2798]: sent [LCP TermReq id=0x3 "No network >>> protocols running"] >>> Jun 26 09:51:02 acay pppd[2798]: rcvd [LCP TermReq id=0xe >>> "^>m\37777777661\000<\37777777715t\000\000\000\000"] >>> Jun 26 09:51:02 acay pppd[2798]: sent [LCP TermAck id=0xe] >>> Jun 26 09:51:04 acay pppd[2798]: Connection terminated. >>> Jun 26 09:51:04 acay pppd[2798]: Connect time 0.6 minutes. >>> Jun 26 09:51:04 acay pppd[2798]: Sent 238 bytes, received 144 bytes. >>> Jun 26 09:51:04 acay pppd[2798]: Connect time 0.6 minutes. >>> Jun 26 09:51:04 acay pppd[2798]: Sent 238 bytes, received 144 bytes. >>> Jun 26 09:51:04 acay pppd[2798]: Exit. >>> >>> >>> pppd options are: >>> lns-pppd-opts "require-chap 192.168.129.1:192.168.129.45 local >>> lcp-echo-interval 10 lcp-echo-failure 5 debug kdebug 1" >>> lac-pppd-opts "noipdefault ipcp-accept-local ipcp-accept-remote local >>> lcp-echo-interval 10 lcp-echo-failure 5 debug kdebug 1" >>> >>> >>> >>> On Sat, June 24, 2006 17:14, Howard Lowndes wrote: >>>> I'm looking for some heavy guidance on an l2tpd/ipsec problem. >>>> Unfortunately l2tpd.org appears to have been hijacked by >>> cybersquatters. >>>> The configuration is a Windows XP Pro (SP2) client sitting behind a >>> NAT >>>> and talking over the Internet to a Linux box running Openswan and >>> l2tpd. >>>> I am using PSK for the ipsec authentication, because I can't get the >>> XP >>>> box to find my privately signed x509 key - but that is a separate >>> issue. >>>> When I bring up the connection window on XP requesting the log in and >>> the >>>> password for the Linux box and then click Connect I can trace >>> everything >>>> that is happening on the Linux box. /var/log/secure shows that the >>> ISAKMP >>>> SA is established and the IPSec SA is established successfully, which >>>> tells me that the ipsec part of the connection appears to be running >>> fine. >>>> If I run l2tpd in non-daemon mode with almost full debugging mode I >>> get >>>> this output repeated several times until the connection attempt >>> eventually >>>> fails and the IPSec SA is torn down: >>>> >>>> l2tpd[19520]: network_thread: recv packet from www.xxx.yyy.zzz, size = >>>> 101, tunnel = 0, call = 0 >>>> l2tpd[19520]: get_call: allocating new tunnel for host >>> www.xxx.yyy.zzz, >>>> port 1701. >>>> l2tpd[19520]: ourtid = 2799, entropy_buf = aef >>>> l2tpd[19520]: check_control: control, cid = 0, Ns = 0, Nr = 0 >>>> l2tpd[19520]: handle_avps: handling avp's for tunnel 2799, call 0 >>>> l2tpd[19520]: message_type_avp: message type 1 >>>> (Start-Control-Connection-Request) >>>> l2tpd[19520]: protocol_version_avp: peer is using version 1, revision >>> 0. >>>> l2tpd[19520]: framing_caps_avp: supported peer frames: sync >>>> l2tpd[19520]: bearer_caps_avp: supported peer bearers: >>>> l2tpd[19520]: firmware_rev_avp: peer reports firmware version 1280 >>>> (0x0500) >>>> l2tpd[19520]: hostname_avp: peer reports hostname 'winxppro' >>>> l2tpd[19520]: vendor_avp: peer reports vendor 'Microsoft' >>>> l2tpd[19520]: assigned_tunnel_avp: using peer's tunnel 30 >>>> l2tpd[19520]: receive_window_size_avp: peer wants RWS of 8. Will use >>> flow >>>> control. >>>> l2tpd[19520]: control_finish: message type is >>>> Start-Control-Connection-Request(1). Tunnel is 30, call is 0. >>>> l2tpd[19520]: control_finish: sending SCCRP >>>> >>>> My /etc/l2tpd/l2tpd.conf file is: >>>> >>>> [global] >>>> auth file = /etc/ppp/chap-secrets >>>> debug avp = yes >>>> debug network = yes >>>> debug packet = no >>>> debug state = yes >>>> debug tunnel = yes >>>> >>>> [lns default] >>>> name = MYVPN >>>> ;exclusive = yes >>>> hostname = host.domain.tld >>>> local ip = 192.168.129.1 >>>> ip range = 192.168.129.41-192.168.129.45 >>>> require authentication = yes >>>> require chap = yes >>>> refuse pap = yes >>>> ;challenge = yes >>>> pppoptfile = /etc/ppp/options.l2tpd >>>> length bit = yes >>>> ppp debug = yes >>>> >>>> It strikes me that either, the Windows box is not trying to start a >>> ppp >>>> sessions, or l2tpd doesn't know how to start a ppp session. >>>> >>>> All and any assistance would be gratefully received. >>>> >>>> >>>> -- >>>> Howard >>>> LANNet Computing Associates <http://lannet.com.au> >>>> When you want a computer system that works, just choose Linux; >>>> When you want a computer system that works, just, choose Microsoft. >>>> >>>> -- >>>> SLUG - Sydney Linux User's Group Mailing List - http://slug.org.au/ >>>> Subscription info and FAQs: http://slug.org.au/faq/mailinglists.html >>>> >>>> >>> >>> -- >>> Howard >>> LANNet Computing Associates <http://lannet.com.au> >>> When you want a computer system that works, just choose Linux; >>> When you want a computer system that works, just, choose Microsoft. >>> >> > > -- Howard. LANNet Computing Associates - Your Linux people <http://lannetlinux.com> When you want a computer system that works, just choose Linux; When you want a computer system that works, just, choose Microsoft. -- Flatter government, not fatter government; abolish the Australian states. -- SLUG - Sydney Linux User's Group Mailing List - http://slug.org.au/ Subscription info and FAQs: http://slug.org.au/faq/mailinglists.html -- SLUG - Sydney Linux User's Group Mailing List - http://slug.org.au/ Subscription info and FAQs: http://slug.org.au/faq/mailinglists.html
