Menu
▾
▴
Re: [pptp-devel] pptp connection problem
|
From: Mathieu F. <mat...@ky...> - 2017-09-08 10:33:52
|
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 |
