[pptp-server] pppd hangs.. Help, pls.
Alexander V Alekseev
alex at ra.zapad.msk.ru
Sat Feb 23 03:37:49 CST 2002
Hello!
I have pptpd server with linux-2.4.9, pppd-2.4.1+mppe
(though only MSCHAP-v2 is really used. No data encryption),
pptpd 1.1.2 . So I get two issues:
1) Windows clients (different versions, win95,98,2000,XP,ME)
connect, and work ok. This can be for a long time (a week or so,
about a hundred connects/disconnects). But suddenly we see in logs:
Feb 23 09:45:18 pptpd[8037]: CTRL: Client 10.0.5.7 control connection started
Feb 23 09:45:18 pptpd[8037]: CTRL: Starting call (launching pppd, opening GRE)
Feb 23 09:45:18 pppd[8038]: pppd 2.4.1 started by root, uid 0
Feb 23 09:45:18 pppd[8038]: tdb_store key failed: Success
Feb 23 09:45:18 pppd[8038]: tdb_store key failed: Success
Feb 23 09:45:18 pppd[8038]: tdb_store failed: Success
Feb 23 09:45:18 pppd[8038]: tdb_store failed: Success
Feb 23 09:45:18 pppd[8038]: Using interface ppp0
Feb 23 09:45:18 pppd[8038]: tdb_store key failed: Success
Feb 23 09:45:18 pppd[8038]: tdb_store failed: Success
Feb 23 09:45:18 pppd[8038]: Connect: ppp0 <--> /dev/pts/0
Feb 23 09:45:18 pppd[8038]: tdb_store failed: Success
Feb 23 09:45:18 pptpd[8037]: Buffering out-of-order packet; got 1 after 4294967295
Feb 23 09:45:18 pptpd[8037]: Packet reorder timeout waiting for 0
Feb 23 09:45:18 pptpd[8037]: Buffering out-of-order packet; got 2 after 0
Feb 23 09:45:18 pppd[8038]: tdb_store failed: Success
Feb 23 09:45:18 pppd[8038]: MSCHAP-v2 peer authentication succeeded for pp20104
Feb 23 09:45:18 pppd[8038]: tdb_store failed: Success
Feb 23 09:45:18 pppd[8038]: tdb_store key failed: Success
Feb 23 09:45:18 pppd[8038]: tdb_store failed: Success
Feb 23 09:45:18 pppd[8038]: local IP address 10.0.0.100
Feb 23 09:45:18 pppd[8038]: remote IP address XXX.247.183.104
Feb 23 09:45:39 pppd[8038]: LCP terminated by peer
Feb 23 09:45:39 pppd[8038]: tdb_store failed: Success
Feb 23 09:45:39 pppd[8038]: Modem hangup
Feb 23 09:45:39 pppd[8038]: Connection terminated.
Feb 23 09:45:39 pppd[8038]: Connect time 0.4 minutes.
Feb 23 09:45:39 pppd[8038]: Sent 5122 bytes, received 7427 bytes.
Feb 23 09:45:39 pppd[8038]: tdb_store failed: Success
Feb 23 09:45:39 pppd[8038]: Exit.
Feb 23 09:45:44 pptpd[8037]: GRE: read error: Bad file descriptor
Feb 23 09:45:44 pptpd[8037]: CTRL: PTY read or GRE write failed (pty,gre)=(-1,-1)
Feb 23 09:45:44 pptpd[8037]: CTRL: Client 10.0.5.7 control connection finished
But if we see in ps aefx output pppd[8038] hangs.
AAnd just after that we see:
Feb 23 10:06:59 pptpd[8041]: CTRL: Client 10.0.5.7 control connection started
Feb 23 10:06:59 pptpd[8041]: CTRL: Starting call (launching pppd, opening GRE)
Feb 23 10:07:29 pptpd[8041]: Buffering out-of-order packet; got 1 after 4294967295
Feb 23 10:07:34 pptpd[8041]: GRE: read error: Bad file descriptor
Feb 23 10:07:34 pptpd[8041]: CTRL: PTY read or GRE write failed (pty,gre)=(-1,-1)
Feb 23 10:07:34 pptpd[8041]: CTRL: Client 10.0.5.7 control connection finished
Feb 23 10:07:44 pptpd[8043]: CTRL: Client 10.0.5.7 control connection started
Feb 23 10:07:44 pptpd[8043]: CTRL: Starting call (launching pppd, opening GRE)
Feb 23 10:08:14 pptpd[8043]: Buffering out-of-order packet; got 1 after 4294967295
Feb 23 10:08:19 pptpd[8043]: GRE: read error: Bad file descriptor
Feb 23 10:08:19 pptpd[8043]: CTRL: PTY read or GRE write failed (pty,gre)=(-1,-1)
Feb 23 10:08:19 pptpd[8043]: CTRL: Client 10.0.5.7 control connection finished
Feb 23 10:10:35 pptpd[8045]: CTRL: Client 10.0.5.7 control connection started
Feb 23 10:10:35 pptpd[8045]: CTRL: Starting call (launching pppd, opening GRE)
Feb 23 10:10:41 pptpd[8045]: Buffering out-of-order packet; got 1 after 4294967295
Feb 23 10:10:46 pptpd[8045]: GRE: read error: Bad file descriptor
Feb 23 10:10:46 pptpd[8045]: CTRL: PTY read or GRE write failed (pty,gre)=(-1,-1)
Feb 23 10:10:46 pptpd[8045]: CTRL: Client 10.0.5.7 control connection finished
Feb 23 10:17:30 pptpd[8047]: CTRL: Client 10.0.5.7 control connection started
Feb 23 10:17:30 pptpd[8047]: CTRL: Starting call (launching pppd, opening GRE)
Feb 23 10:18:00 pptpd[8047]: Buffering out-of-order packet; got 1 after 4294967295
Feb 23 10:18:05 pptpd[8047]: GRE: read error: Bad file descriptor
Feb 23 10:18:05 pptpd[8047]: CTRL: PTY read or GRE write failed (pty,gre)=(-1,-1)
Feb 23 10:18:05 pptpd[8047]: CTRL: Client 10.0.5.7 control connection finished
... And so on (Each time one more pppd is added...).
So, we see something like:
28512 ? R 138:17 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
28683 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
28685 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
28812 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
28814 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
28816 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
29443 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
30570 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
30572 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
30699 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
30701 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
31453 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
31455 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
31457 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
31959 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
31961 ? S 0:00 /usr/sbin/pppd local file /etc/ppp/options.pptp 921600
If we kill the first pppd, the second starts eating all cpu. And so on.
We have to kill all those pppd, to let anyone connect...
Can anyone help?
2) Sometimes pppd hangs on connect immediately. Windows client says: "Verifying
username and password", waits, than says Error 650. In logs something like:
Feb 22 19:50:38 pptpd[6472]: CTRL: Client 10.0.48.3 control connection started
Feb 22 19:50:38 pptpd[6472]: CTRL: Starting call (launching pppd, opening GRE)
Feb 22 19:50:38 pppd[6473]: pppd 2.4.1 started by root, uid 0
Feb 22 19:51:08 pptpd[6472]: Buffering out-of-order packet; got 1 after 4294967295
Feb 22 19:51:13 pptpd[6472]: GRE: read error: Bad file descriptor
Feb 22 19:51:13 pptpd[6472]: CTRL: PTY read or GRE write failed (pty,gre)=(-1,-1)
Feb 22 19:51:13 pptpd[6472]: CTRL: Client 10.0.48.3 control connection finished
And then we see everything just like in case 1) .
Any ideas?
Bye. Alex.
--
Alexander V Alekseev, AVA37-RIPN
RA Telecom NOC
+7 095 231-27-23
More information about the pptp-server
mailing list