[pptp-server] Errors 650 629 645

[John Sutton]

Hi David

I've downloaded and built the latest CVS 0.8.9pre and things are looking up!  Unfortunately the connection over a dialup (which is of course the one I'm interested in ;-) is still not working ;-(  Here are the results.

Clean boot client, LAN connection:

Jun  6 13:59:18 masq PPTPD [4189]: starting PPTPCTRL to handle client
Jun  6 13:59:18 masq PPTPD [4189]: clientSocket = 7 
Jun  6 13:59:18 masq PPTPD [4189]: Control Pipe = 6 
Jun  6 13:59:18 masq PPTPD [4189]: local IP = 192.168.2.30 
Jun  6 13:59:18 masq PPTPD [4189]: remote IP = 192.168.2.40 
Jun  6 13:59:18 masq PPTPD [4189]: pppd speed = 115200 
Jun  6 13:59:18 masq PPTPD [4189]: CTRL_PIPE = 6
Jun  6 13:59:18 masq PPTPD [4189]: Extracting the IP of the client...
Jun  6 13:59:18 masq PPTPD [4189]: CTRL: Now attempting to handle PPTP control connection.
Jun  6 13:59:18 masq PPTPD [4189]: CTRL: I've made a suitable START_CTRL_CONN_RPLY..
Jun  6 13:59:18 masq PPTPD [4189]: CTRL: I've made a suitable OUT_CALL_RPLY..
Jun  6 13:59:18 masq PPTPD [4189]: CTRL: permission to launch pppd/gre granted
Jun  6 13:59:18 masq PPTPD [4189]: CTRL: Calling startCall()
Jun  6 13:59:18 masq PPTPD [4189]: CTRL: ttydev = /dev/ttya0
Jun  6 13:59:18 masq PPTPD [4189]: CTRL: ptydev = /dev/ptya0
Jun  6 13:59:18 masq PPTPD [4190]: CTRL (PPPD Launcher): Connection speed = 115200
Jun  6 13:59:19 masq PPTPD [4189]: CTRL: this session finished...
Jun  6 13:59:19 masq PPTPD [4189]: CTRL: manger has been informed of our death

At this point the client has thrown a 629 (note: not a 650 as before with 0.8.7) which I have not as yet OK'd.  So I OK it (nothing results in the log) and then retry.  This usually succeeds but if you wait too long it *sometimes* does the same as above again.

So this is usable (albeit a bit messy) because there is no need to kill anything on the server.  However, the situation when the connection is over a dialup is still unusable (but we're getting close ;-) :

Clean boot client, dialup connection:

Jun  6 13:39:20 masq PPTPD [4103]: dots=192 168 2 30-33
Jun  6 13:39:20 masq PPTPD [4103]: dots=192 168 2 40-43
Jun  6 13:39:20 masq PPTPD [4103]: Manager Started
Jun  6 13:40:59 masq PPTPD [4106]: starting PPTPCTRL to handle client
Jun  6 13:40:59 masq PPTPD [4106]: clientSocket = 7
Jun  6 13:40:59 masq PPTPD [4106]: Control Pipe = 6
Jun  6 13:40:59 masq PPTPD [4106]: local IP = 192.168.2.30
Jun  6 13:40:59 masq PPTPD [4106]: remote IP = 192.168.2.40
Jun  6 13:40:59 masq PPTPD [4106]: pppd speed = 115200
Jun  6 13:40:59 masq PPTPD [4106]: CTRL_PIPE = 6
Jun  6 13:40:59 masq PPTPD [4106]: Extracting the IP of the client...
Jun  6 13:40:59 masq PPTPD [4106]: CTRL: Now attempting to handle PPTP control c
onnection.
Jun  6 13:40:59 masq PPTPD [4106]: CTRL: I've made a suitable START_CTRL_CONN_RP
LY..
Jun  6 13:41:00 masq PPTPD [4106]: CTRL: I've made a suitable OUT_CALL_RPLY..
Jun  6 13:41:00 masq PPTPD [4106]: CTRL: permission to launch pppd/gre granted
Jun  6 13:41:00 masq PPTPD [4106]: CTRL: Calling startCall()
Jun  6 13:41:00 masq PPTPD [4106]: CTRL: ttydev = /dev/ttya0
Jun  6 13:41:00 masq PPTPD [4106]: CTRL: ptydev = /dev/ptya0
Jun  6 13:41:00 masq PPTPD [4107]: CTRL (PPPD Launcher): Connection speed = 1152
00
Jun  6 13:41:00 masq PPTPD [4106]: CTRL: this session finished...
Jun  6 13:41:00 masq PPTPD [4106]: CTRL: manger has been informed of our death

So on this first attempt the client has thrown a 645 *and* cleared the connection before I have OK'ed the "Error: 645" dialogue and before the pppd has had chance to send anything at all.  This is exactly the same debug trace as with the "LAN first attempt" case except that we get a 645 rather than a 629.  But on subsequent attempts:

Jun  6 13:41:31 masq PPTPD [4113]: starting PPTPCTRL to handle client
Jun  6 13:41:31 masq PPTPD [4113]: clientSocket = 7
Jun  6 13:41:31 masq PPTPD [4113]: Control Pipe = 6
Jun  6 13:41:31 masq PPTPD [4113]: local IP = 192.168.2.30
Jun  6 13:41:31 masq PPTPD [4113]: remote IP = 192.168.2.40
Jun  6 13:41:31 masq PPTPD [4113]: pppd speed = 115200
Jun  6 13:41:31 masq PPTPD [4113]: CTRL_PIPE = 6
Jun  6 13:41:31 masq PPTPD [4113]: Extracting the IP of the client...
Jun  6 13:41:31 masq PPTPD [4113]: CTRL: Now attempting to handle PPTP control c
onnection.
Jun  6 13:41:31 masq PPTPD [4113]: CTRL: I've made a suitable START_CTRL_CONN_RP
LY..
Jun  6 13:41:31 masq PPTPD [4113]: CTRL: I've made a suitable OUT_CALL_RPLY..
Jun  6 13:41:31 masq PPTPD [4113]: CTRL: permission to launch pppd/gre granted
Jun  6 13:41:31 masq PPTPD [4113]: CTRL: Calling startCall()
Jun  6 13:41:31 masq PPTPD [4113]: CTRL: ttydev = /dev/ttya0
Jun  6 13:41:31 masq PPTPD [4113]: CTRL: ptydev = /dev/ptya0
Jun  6 13:41:31 masq PPTPD [4114]: CTRL (PPPD Launcher): Connection speed = 1152
00
Jun  6 13:41:32 masq pppd[4115]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth c
hap MD5> <magic 0x5c8a8a1a> <pcomp> <accomp>]

The client again throws a 645 but the connection stays open until (at some point) I OK the "Error: 645" dialogue:

Jun  6 13:41:44 masq last message repeated 4 times
Jun  6 13:41:45 masq PPTPD [4113]: CTRL: I've made a suitable CALL DISCONNECT re
ply packet..
Jun  6 13:41:45 masq PPTPD [4113]: We have told the client we are disconnecting.
..
Jun  6 13:41:45 masq PPTPD [4113]: CTRL: this session finished...
Jun  6 13:41:45 masq PPTPD [4113]: CTRL: manger has been informed of our death

If instead I wait for the LCP "negotiation" (well, not exactly that since the other end is not talking ;-) to timeout before OK'ing the dialogue I get:

Jun  6 14:16:20 masq last message repeated 9 times
Jun  6 14:16:23 masq PPTPD [4296]: CTRL: this session finished...
Jun  6 14:16:23 masq PPTPD [4296]: CTRL: manger has been informed of our death

I can then OK the 645 and nothing happens in the log.  Subsequent attempts follow the same course.

I pretty desperate to get this going!  If there is any further testing I can do, please let me know.  Thanks for your efforts this far.

John

At 14:57 06/06/99 +0800, you wrote:
>
>Please try using the latest CVS version.  I fixed a rather serious bug in
>there with the pppd's hanging around after other stuff is gone (since file
>descriptors weren't being closed before exec'ing the pppd, this included
>keeping open a copy of the network socket, both halves of the pty/tty pair,
>a socketpair intended for communication between some other processes and
>so on).  This could quite possibly solve your problem.
>
>David.

***************************************************
John Sutton
SCL Computer Services
URL http://www.scl.co.uk/
Tel. +44 (0) 1239 621021
***************************************************