Hello all,
I’m a newbie to the forum and to Linux. My problem relates to a PPTP server I’m trying to set up on an openSuSE machine. We have Linux clients which establish PPTP tunnels currently to a Mac OS. For operational reasons we want to change this to one of our under-used Linux machines and make the Mac redundant. I have followed several google-found instructions on how to set this up with limited success. I cannot get the tunnels to establish and I am hoping you can help me with why this might be. I have “syslog” traces from the server and the client which are below:
Server trace:
Jul 5 16:32:45 vision pptpd[19962]: CTRL: Received PPTP Control Message (type: 7)
Jul 5 16:32:45 vision pptpd[19962]: CTRL: Set parameters to 10000000 maxbps, 3 window size
Jul 5 16:32:45 vision pptpd[19962]: CTRL: Made a OUT CALL RPLY packet
Jul 5 16:32:45 vision pptpd[19962]: CTRL: Starting call (launching pppd, opening GRE)
Jul 5 16:32:45 vision pptpd[19962]: CTRL: pty_fd = 6
Jul 5 16:32:45 vision pptpd[19962]: CTRL: tty_fd = 7
Jul 5 16:32:45 vision pptpd[19962]: CTRL: I wrote 32 bytes to the client.
Jul 5 16:32:45 vision pptpd[19962]: CTRL: Sent packet to client
Jul 5 16:32:45 vision pptpd[19963]: CTRL (PPPD Launcher): program binary = /usr/sbin/pppd
Jul 5 16:32:45 vision pptpd[19963]: CTRL (PPPD Launcher): local address = 192.168.251.251
Jul 5 16:32:45 vision pptpd[19963]: CTRL (PPPD Launcher): remote address = 192.168.251.50
Jul 5 16:32:45 vision pppd[19963]: pppd 2.4.5 started by root, uid 0
Jul 5 16:32:45 vision pppd[19963]: using channel 98
Jul 5 16:32:45 vision pppd[19963]: Using interface ppp0
Jul 5 16:32:45 vision pppd[19963]: Connect: ppp0 <--> /dev/pts/2
Jul 5 16:32:45 vision pppd[19963]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x5c9ae402> <pcomp> <accomp>]
Jul 5 16:32:45 vision pptpd[19962]: GRE: buffering packet #1 (expecting #0, lost or reordered)
Jul 5 16:32:47 vision pppd[19963]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x5c9ae402> <pcomp> <accomp>]
Jul 5 16:32:48 vision pptpd[19962]: GRE: timeout waiting for 1 packets
Jul 5 16:32:48 vision pptpd[19962]: GRE: accepting #1 from queue
Jul 5 16:32:48 vision pptpd[19962]: GRE: accepting packet #2
Jul 5 16:32:48 vision pppd[19963]: rcvd [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0x275eaaa6> <pcomp> <accomp>]
Jul 5 16:32:48 vision pppd[19963]: sent [LCP ConfAck id=0x1 <mru 1400> <asyncmap 0x0> <magic 0x275eaaa6> <pcomp> <accomp>]
Jul 5 16:32:48 vision pppd[19963]: rcvd [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0x275eaaa6> <pcomp> <accomp>]
Jul 5 16:32:48 vision pppd[19963]: sent [LCP ConfAck id=0x1 <mru 1400> <asyncmap 0x0> <magic 0x275eaaa6> <pcomp> <accomp>]
Jul 5 16:32:49 vision pppd[19963]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x5c9ae402> <pcomp> <accomp>]
Jul 5 16:32:51 vision pptpd[19962]: GRE: accepting packet #3
Jul 5 16:32:51 vision pppd[19963]: rcvd [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0x275eaaa6> <pcomp> <accomp>]
Jul 5 16:32:51 vision pppd[19963]: sent [LCP ConfAck id=0x1 <mru 1400> <asyncmap 0x0> <magic 0x275eaaa6> <pcomp> <accomp>]
Jul 5 16:32:51 vision pppd[19963]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x5c9ae402> <pcomp> <accomp>]
Jul 5 16:32:53 vision pppd[19963]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x5c9ae402> <pcomp> <accomp>]
Jul 5 16:32:54 vision pptpd[19962]: GRE: accepting packet #4
Jul 5 16:32:54 vision pppd[19963]: rcvd [LCP ConfReq id=0x1 <mru 1400> <asyncmap 0x0> <magic 0x275eaaa6> <pcomp> <accomp>]
Jul 5 16:32:54 vision pppd[19963]: sent [LCP ConfAck id=0x1 <mru 1400> <asyncmap 0x0> <magic 0x275eaaa6> <pcomp> <accomp>]
Jul 5 16:32:55 vision pppd[19963]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x5c9ae402> <pcomp> <accomp>]
Jul 5 16:32:57 vision pppd[19963]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x5c9ae402> <pcomp> <accomp>]
Jul 5 16:32:58 vision pptpd[19962]: CTRL: Received PPTP Control Message (type: 7)
Jul 5 16:32:58 vision pptpd[19962]: CTRL: Asked to allocate call id when call open, not handled well
Jul 5 16:32:58 vision pptpd[19962]: CTRL: Set parameters to 10000000 maxbps, 3 window size
Jul 5 16:32:58 vision pptpd[19962]: CTRL: Made a OUT CALL RPLY packet
Jul 5 16:32:58 vision pptpd[19962]: CTRL: Request to open call when call is already open, closing
Jul 5 16:32:58 vision pptpd[19962]: CTRL: Starting call (launching pppd, opening GRE)
Jul 5 16:32:58 vision pptpd[19962]: CTRL: pty_fd = 6
Jul 5 16:32:58 vision pptpd[19962]: CTRL: tty_fd = 7
Jul 5 16:32:58 vision pptpd[19962]: CTRL: I wrote 32 bytes to the client.
Jul 5 16:32:58 vision pptpd[19962]: CTRL: Sent packet to client
Jul 5 16:32:58 vision pppd[19963]: Modem hangup
Jul 5 16:32:58 vision pppd[19963]: Connection terminated.
Jul 5 16:32:58 vision avahi-daemon[847]: Withdrawing workstation service for ppp0.
Jul 5 16:32:58 vision pptpd[19988]: CTRL (PPPD Launcher): program binary = /usr/sbin/pppd
Jul 5 16:32:58 vision pptpd[19988]: CTRL (PPPD Launcher): local address = 192.168.251.251
Jul 5 16:32:58 vision pptpd[19988]: CTRL (PPPD Launcher): remote address = 192.168.251.50
Jul 5 16:32:58 vision pppd[19963]: Exit.
Jul 5 16:32:58 vision pppd[19988]: pppd 2.4.5 started by splicecom, uid 0
Jul 5 16:32:58 vision pppd[19988]: using channel 99
Jul 5 16:32:58 vision pppd[19988]: Using interface ppp0
Jul 5 16:32:58 vision pppd[19988]: Connect: ppp0 <--> /dev/pts/3
Jul 5 16:32:58 vision pppd[19988]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0xe337cb75> <pcomp> <accomp>]
Jul 5 16:32:59 vision pptpd[19962]: GRE: buffering packet #1 (expecting #0, lost or reordered)
Jul 5 16:33:00 vision pppd[19988]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0xe337cb75> <pcomp> <accomp>]
Jul 5 16:33:02 vision pptpd[19962]: GRE: timeout waiting for 1 packets
Jul 5 16:33:02 vision pptpd[19962]: GRE: accepting #1 from queue
Jul 5 16:33:02 vision pptpd[19962]: GRE: accepting packet #2
Jul 5 16:33:02 vision pppd[19988]: rcvd [LCP ConfReq id=0x2 <mru 1400> <asyncmap 0x0> <magic 0x5d9de8d6> <pcomp> <accomp>]
Jul 5 16:33:02 vision pppd[19988]: sent [LCP ConfAck id=0x2 <mru 1400> <asyncmap 0x0> <magic 0x5d9de8d6> <pcomp> <accomp>]
Jul 5 16:33:02 vision pppd[19988]: rcvd [LCP ConfReq id=0x2 <mru 1400> <asyncmap 0x0> <magic 0x5d9de8d6> <pcomp> <accomp>]
Jul 5 16:33:02 vision pppd[19988]: sent [LCP ConfAck id=0x2 <mru 1400> <asyncmap 0x0> <magic 0x5d9de8d6> <pcomp> <accomp>]
Jul 5 16:33:02 vision pppd[19988]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0xe337cb75> <pcomp> <accomp>]
Jul 5 16:33:03 vision pptpd[19962]: CTRL: Received PPTP Control Message (type: 12)
Jul 5 16:33:03 vision pptpd[19962]: CTRL: Made a CALL DISCONNECT RPLY packet
Jul 5 16:33:03 vision pptpd[19962]: CTRL: Received CALL CLR request (closing call)
Jul 5 16:33:03 vision pptpd[19962]: CTRL: Reaping child PPP[19988]
Jul 5 16:33:03 vision pppd[19988]: Modem hangup
Jul 5 16:33:03 vision pppd[19988]: Connection terminated.
Jul 5 16:33:03 vision avahi-daemon[847]: Withdrawing workstation service for ppp0.
Jul 5 16:33:03 vision pppd[19988]: Exit.
Jul 5 16:33:03 vision pptpd[19962]: CTRL: Client 192.168.252.232 control connection finished
Jul 5 16:33:03 vision pptpd[19962]: CTRL: Exiting now
Jul 5 16:33:03 vision pptpd[12865]: MGR: Reaped child 19962
Client trace:
Jul 5 16:32:45 (none) daemon.notice pppd[1639]: pppd 2.4.3 started by root, uid 0
Jul 5 16:32:45 (none) daemon.info pppd[1639]: Using interface ppp0
Jul 5 16:32:45 (none) daemon.notice pppd[1639]: Connect: ppp0 <--> /dev/ttyp0
Jul 5 16:32:45 (none) daemon.notice pptp[1641]: anon log[main:pptp.c:237]: The synchronous pptp option is NOT activated
Jul 5 16:32:45 (none) daemon.notice pptp[1646]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 1 'Start-Control-Connection-Request'
Jul 5 16:32:45 (none) daemon.notice pptp[1646]: anon log[ctrlp_disp:pptp_ctrl.c:714]: Received Start Control Connection Reply
Jul 5 16:32:45 (none) daemon.notice pptp[1646]: anon log[ctrlp_disp:pptp_ctrl.c:748]: Client connection established.
Jul 5 16:32:46 (none) daemon.notice pptp[1646]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 7 'Outgoing-Call-Request'
Jul 5 16:32:46 (none) daemon.notice pptp[1646]: anon log[ctrlp_disp:pptp_ctrl.c:834]: Received Outgoing Call Reply.
Jul 5 16:32:46 (none) daemon.notice pptp[1646]: anon log[ctrlp_disp:pptp_ctrl.c:873]: Outgoing call established (call ID 0, peer's call ID 1280).
Jul 5 16:32:58 (none) daemon.warn pppd[1639]: LCP: timeout sending Config-Requests
Jul 5 16:32:58 (none) daemon.notice pppd[1639]: Connection terminated.
Jul 5 16:32:58 (none) daemon.info pppd[1639]: Using interface ppp0
Jul 5 16:32:58 (none) daemon.notice pppd[1639]: Connect: ppp0 <--> /dev/ttyp2
Jul 5 16:32:58 (none) daemon.notice pptp[1679]: anon log[main:pptp.c:237]: The synchronous pptp option is NOT activated
Jul 5 16:32:58 (none) daemon.notice pptp[1646]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 7 'Outgoing-Call-Request'
Jul 5 16:32:58 (none) daemon.notice pptp[1646]: anon log[ctrlp_disp:pptp_ctrl.c:834]: Received Outgoing Call Reply.
Jul 5 16:32:58 (none) daemon.notice pptp[1646]: anon log[ctrlp_disp:pptp_ctrl.c:873]: Outgoing call established (call ID 1, peer's call ID 1281).
Jul 5 16:33:03 (none) daemon.warn pppd[1639]: tcflush failed: Bad file descriptor
Jul 5 16:33:03 (none) daemon.info pppd[1639]: Exit.
Jul 5 16:33:03 (none) daemon.warn pptp[1679]: anon warn[decaps_hdlc:pptp_gre.c:196]: short read (-1): Input/output error
Jul 5 16:33:03 (none) daemon.warn pptp[1679]: anon warn[decaps_hdlc:pptp_gre.c:197]: pppd may have shutdown, see pppd log
Jul 5 16:33:03 (none) user.notice VPN: PPP negotiation failed
Jul 5 16:33:03 (none) daemon.notice pptp[1646]: anon log[callmgr_main:pptp_callmgr.c:249]: Closing connection
Jul 5 16:33:03 (none) daemon.notice pptp[1646]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 12 'Call-Clear-Request'
Jul 5 16:33:03 (none) daemon.notice pptp[1646]: anon log[callmgr_main:pptp_callmgr.c:249]: Closing connection
Jul 5 16:33:03 (none) daemon.notice pptp[1646]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 12 'Call-Clear-Request'
Jul 5 16:33:05 (none) daemon.notice pptp[1646]: anon log[pptp_send_ctrl_packet:pptp_ctrl.c:599]: write error: Broken pipe
Jul 5 16:33:05 (none) daemon.notice pptp[1646]: anon log[call_callback:pptp_callmgr.c:77]: Closing connection
Jul 5 16:33:05 (none) daemon.notice pptp[1646]: anon log[pptp_conn_close:pptp_ctrl.c:425]: Closing PPTP connection
Jul 5 16:33:05 (none) daemon.notice pptp[1646]: anon log[pptp_send_ctrl_packet:pptp_ctrl.c:599]: write error: Bad file descriptor
I can see some obvious errors in the traces, trouble is I don’t know what they mean or how to resolve them. Any help you guys can offer would be greatly appreciated.
Thanks, Matt.