Re: [pptp-devel] pptp connection problem

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

This now is an entirely different problem to your previous post, even
though you might think it is the same.

Your logs show successful establishment of PPP over GRE, with IP
addresses assigned.

However, the TCP port 1723 connection hangs, and pptpd does not
receive reply to PPTP ECHO request.  Consequence is shutdown of
connection by pptpd after 2.5 minutes.  A known problem pattern.

Cause will be either;

1.  client or server routing table change that redirects all packets
into tunnel, without a host route for conveying the GRE and TCP port
1723 connection,

2.  intermediary such as a gateway or node outside your control that
fails to pass PPTP, either by policy or accident.  Very common when an
ISP uses NAT.

Please try OpenVPN if you know your network uses NAT.

Please use tcpdump on both the server and the client to record the
negotiation.  Take note of security warning;

http://pptpclient.sourceforge.net/howto-diagnosis.phtml#tcpdump

Also interesting is that Network Manager has become involved in the
connection.  If you think Network Manager may be responsible, please
refer to Network Manager mailing lists.  ;-)  Or you may instruct
Network Manager in configuration file to ignore interface.

On Fri, Sep 08, 2017 at 12:33:19PM +0200, Mathieu Fortin wrote:
> Hello,
> 
> Before all I give you a thanks for the rapidity of your answer.
> 
> I activated pppd debug in /etc/ppp/options.
> 
> Following, you'll find an extract of the server /var/log/syslog | grep pp.
> First the 3G embedded pptp client arrived to connect to the server I
> disconnected it stopping its electrical alimentation and I arrived to
> obtains the connection problem which is driving me crazy. Those 2 phases are
> separated by an empty line.
> 
> Sep  8 12:02:42 localhost pptpd[29135]: CTRL: Client 37.166.227.190 control
> connection started
> Sep  8 12:02:43 localhost pptpd[29135]: CTRL: Starting call (launching pppd,
> opening GRE)
> Sep  8 12:02:43 localhost pppd[29136]: Plugin
> /usr/lib/pptpd/pptpd-logwtmp.so loaded.
> Sep  8 12:02:43 localhost pppd[29136]: pptpd-logwtmp: $Version$
> Sep  8 12:02:43 localhost pppd[29136]: pppd 2.4.6 started by root, uid 0
> Sep  8 12:02:43 localhost pppd[29136]: using channel 124
> Sep  8 12:02:43 localhost pppd[29136]: Using interface ppp1
> Sep  8 12:02:43 localhost pppd[29136]: Connect: ppp1 <--> /dev/pts/5
> Sep  8 12:02:43 localhost pppd[29136]: sent [LCP ConfReq id=0x1 <asyncmap
> 0x0> <auth chap MS-v2> <magic 0xe1e980b0> <pcomp> <accomp>]
> Sep  8 12:02:43 localhost pptpd[29135]: GRE: Bad checksum from pppd.
> Sep  8 12:02:43 localhost NetworkManager[16755]: <info> (ppp1): new Generic
> device (driver: 'unknown' ifindex: 128)
> Sep  8 12:02:43 localhost NetworkManager[16755]: <info> (ppp1): exported as
> /org/freedesktop/NetworkManager/Devices/70
> Sep  8 12:02:43 localhost NetworkManager[16755]: <info> devices added (path:
> /sys/devices/virtual/net/ppp1, iface: ppp1)
> Sep  8 12:02:43 localhost NetworkManager[16755]: <info> device added (path:
> /sys/devices/virtual/net/ppp1, iface: ppp1): no ifupdown configuration
> found.
> Sep  8 12:02:44 localhost pppd[29136]: rcvd [LCP ConfReq id=0x1 <asyncmap
> 0x0> <magic 0x1d5b3b49> <pcomp> <accomp>]
> Sep  8 12:02:44 localhost pppd[29136]: sent [LCP ConfAck id=0x1 <asyncmap
> 0x0> <magic 0x1d5b3b49> <pcomp> <accomp>]
> Sep  8 12:02:44 localhost pppd[29136]: rcvd [LCP ConfAck id=0x1 <asyncmap
> 0x0> <auth chap MS-v2> <magic 0xe1e980b0> <pcomp> <accomp>]
> Sep  8 12:02:44 localhost pppd[29136]: sent [LCP EchoReq id=0x0
> magic=0xe1e980b0]
> Sep  8 12:02:44 localhost pppd[29136]: sent [CHAP Challenge id=0x85
> <273ab0af9f879b2e6c74dc199d642a3d>, name = "pptpd"]
> Sep  8 12:02:44 localhost pppd[29136]: rcvd [LCP EchoReq id=0x0
> magic=0x1d5b3b49]
> Sep  8 12:02:44 localhost pppd[29136]: sent [LCP EchoRep id=0x0
> magic=0xe1e980b0]
> Sep  8 12:02:44 localhost pppd[29136]: rcvd [LCP EchoRep id=0x0
> magic=0x1d5b3b49]
> Sep  8 12:02:44 localhost pppd[29136]: rcvd [CHAP Response id=0x85 <b386930840b646e6a3fc54edb4785a13000000000000000081e20717606ba7bc09f8a4ea16b089da05591354267f387000>,
> name = "GATEWAY-0004"]
> Sep  8 12:02:44 localhost pppd[29136]: sent [CHAP Success id=0x85
> "S=C358981D7021578E86C16C40DC804316A70ED03F M=Access granted"]
> Sep  8 12:02:44 localhost pppd[29136]: peer from calling number
> 37.166.227.190 authorized
> Sep  8 12:02:44 localhost pppd[29136]: sent [CCP ConfReq id=0x1 <mppe +H -M
> +S -L -D -C>]
> Sep  8 12:02:45 localhost pppd[29136]: rcvd [CCP ConfReq id=0x1 <mppe +H -M
> +S -L -D -C>]
> Sep  8 12:02:45 localhost pppd[29136]: sent [CCP ConfAck id=0x1 <mppe +H -M
> +S -L -D -C>]
> Sep  8 12:02:45 localhost pppd[29136]: rcvd [CCP ConfAck id=0x1 <mppe +H -M
> +S -L -D -C>]
> Sep  8 12:02:45 localhost pppd[29136]: MPPE 128-bit stateless compression
> enabled
> Sep  8 12:02:45 localhost pppd[29136]: sent [IPCP ConfReq id=0x1 <compress
> VJ 0f 01> <addr 10.9.0.1>]
> Sep  8 12:02:45 localhost pppd[29136]: rcvd [IPCP ConfReq id=0x1 <compress
> VJ 0f 01> <addr 0.0.0.0>]
> Sep  8 12:02:45 localhost pppd[29136]: sent [IPCP ConfNak id=0x1 <addr
> 10.9.0.4>]
> Sep  8 12:02:45 localhost pppd[29136]: rcvd [IPCP ConfAck id=0x1 <compress
> VJ 0f 01> <addr 10.9.0.1>]
> Sep  8 12:02:46 localhost pppd[29136]: rcvd [IPCP ConfReq id=0x2 <compress
> VJ 0f 01> <addr 10.9.0.4>]
> Sep  8 12:02:46 localhost pppd[29136]: sent [IPCP ConfAck id=0x2 <compress
> VJ 0f 01> <addr 10.9.0.4>]
> Sep  8 12:02:46 localhost pppd[29136]: Cannot determine ethernet address for
> proxy ARP
> Sep  8 12:02:46 localhost pppd[29136]: local  IP address 10.9.0.1
> Sep  8 12:02:46 localhost pppd[29136]: remote IP address 10.9.0.4
> Sep  8 12:02:46 localhost pppd[29136]: pptpd-logwtmp.so ip-up ppp1
> GATEWAY-0004 37.166.227.190
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> (ppp1): device state
> change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> (ppp1): device state
> change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> starting connection 'ppp1'
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 1 of 5 (Device Prepare) scheduled...
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 1 of 5 (Device Prepare) started...
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> (ppp1): device state
> change: disconnected -> prepare (reason 'none') [30 40 0]
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 2 of 5 (Device Configure) scheduled...
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 1 of 5 (Device Prepare) complete.
> Sep  8 12:02:46 localhost pppd[29136]: Script /etc/ppp/ip-up started (pid
> 29142)
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 2 of 5 (Device Configure) starting...
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> (ppp1): device state
> change: prepare -> config (reason 'none') [40 50 0]
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 2 of 5 (Device Configure) successful.
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 3 of 5 (IP Configure Start) scheduled.
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 2 of 5 (Device Configure) complete.
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 3 of 5 (IP Configure Start) started...
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> (ppp1): device state
> change: config -> ip-config (reason 'none') [50 70 0]
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 5 of 5 (IPv4 Configure Commit) scheduled...
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 3 of 5 (IP Configure Start) complete.
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 5 of 5 (IPv4 Commit) started...
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> (ppp1): device state
> change: ip-config -> ip-check (reason 'none') [70 80 0]
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> Stage 5 of 5 (IPv4 Commit) complete.
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> (ppp1): device state
> change: ip-check -> secondaries (reason 'none') [80 90 0]
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> (ppp1): device state
> change: secondaries -> activated (reason 'none') [90 100 0]
> Sep  8 12:02:46 localhost NetworkManager[16755]: <info> Activation (ppp1)
> successful, device activated.
> Sep  8 12:02:46 localhost pppd[29136]: Script /etc/ppp/ip-up finished (pid
> 29142), status = 0x0
> Sep  8 12:02:46 localhost nm-dispatcher: Dispatching action 'up' for ppp1
> Sep  8 12:05:14 localhost pptpd[29135]: CTRL: Session timed out, ending call
> Sep  8 12:05:14 localhost pptpd[29135]: CTRL: Reaping child PPP[29136]
> Sep  8 12:05:14 localhost pppd[29136]: Modem hangup
> Sep  8 12:05:14 localhost pppd[29136]: pptpd-logwtmp.so ip-down ppp1
> Sep  8 12:05:14 localhost pppd[29136]: Connect time 2.5 minutes.
> Sep  8 12:05:14 localhost pppd[29136]: Sent 0 bytes, received 0 bytes.
> Sep  8 12:05:14 localhost pppd[29136]: Script /etc/ppp/ip-down started (pid
> 29199)
> Sep  8 12:05:14 localhost pppd[29136]: MPPE disabled
> Sep  8 12:05:14 localhost pppd[29136]: sent [LCP TermReq id=0x2 "MPPE
> disabled"]
> Sep  8 12:05:14 localhost pppd[29136]: Connection terminated.
> Sep  8 12:05:14 localhost pppd[29136]: Waiting for 1 child processes...
> Sep  8 12:05:14 localhost pppd[29136]:   script /etc/ppp/ip-down, pid 29199
> Sep  8 12:05:14 localhost pppd[29136]: Script /etc/ppp/ip-down finished (pid
> 29199), status = 0x0
> Sep  8 12:05:14 localhost pppd[29136]: Exit.
> Sep  8 12:05:14 localhost pptpd[29135]: CTRL: Client 37.166.227.190 control
> connection finished
> Sep  8 12:05:14 localhost NetworkManager[16755]: <info> (ppp1): device state
> change: activated -> unmanaged (reason 'removed') [100 10 36]
> Sep  8 12:05:14 localhost NetworkManager[16755]: <info> (ppp1): deactivating
> device (reason 'removed') [36]
> Sep  8 12:05:14 localhost NetworkManager[16755]: <info> devices removed
> (path: /sys/devices/virtual/net/ppp1, iface: ppp1)
> Sep  8 12:05:14 localhost nm-dispatcher: Dispatching action 'down' for ppp1
> 
> Sep  8 12:05:34 localhost pptpd[29229]: CTRL: Client 37.168.195.42 control
> connection started
> Sep  8 12:09:34 localhost pptpd[29229]: CTRL: Session timed out, ending call
> Sep  8 12:09:34 localhost pptpd[29229]: CTRL: Reaping child PPP[0]
> Sep  8 12:09:34 localhost pptpd[29229]: CTRL: Client 37.168.195.42 control
> connection finished
> 
> Again thanks for your help.
> 
> 
> 
> Le 07/09/2017 à 23:07, James Cameron a écrit :
> >On Thu, Sep 07, 2017 at 03:10:12PM +0200, Mathieu Fortin wrote:
> >>     sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x54966ab8> <pcomp>
> >><accomp>]
> >>     LCP: timeout sending Config-Requests
> >Very common problem.
> >http://pptpclient.sourceforge.net/howto-diagnosis.phtml#client_no_gre_rx
> >
> >Won't speculate on causes until you've gathered more information.
> >
> >>and Server side:
> >>     Sep  7 14:01:51 COORD-00020 pptpd[27671]: CTRL: Sending ECHO REQ id 1
> >>     Sep  7 14:01:51 COORD-00020 pptpd[27671]: CTRL: Made a ECHO REQ packet
> >>     Sep  7 14:01:51 COORD-00020 pptpd[27671]: CTRL: I wrote 16 bytes to the
> >>client.
> >>     Sep  7 14:01:51 COORD-00020 pptpd[27671]: CTRL: Sent packet to client
> >Your server log does not contain pppd debugging, please add that,
> >capture the client and server logs for the same attempt, and post them.
> >
> 
> -- 
> Apprenti ingénieur des systèmes d'informations
> 

-- 
James Cameron
http://quozl.netrek.org/