Topic: Where to find PPTP log to diag problems?

[Jeff Peters]

Hello,

I'm having trouble with PPTP from a WinXP pro client to my SME6 beta 3 box. Connection works well but after approximately 3 minutes I am disconnected and cannot reconnect unless the SME box is rebooted.

I'm looking for the log file to diagnose the problem but cannot find it.

Any suggestions? I have been unsuccessful finding anything of the topic by searching this forum.

Thanks in advance.

[Jeff Peters]

So far I have found the following using grep 'pptp' /var/log/messages

Nov 22 12:06:50 sme60b3 pptpd[2140]: MGR: Manager process started
Nov 22 12:07:51 sme60b3 pptpd[2140]: MGR: dropped small initial connection
Nov 22 12:12:29 sme60b3 pptpd[2140]: MGR: dropped small initial connection
Nov 22 12:16:53 sme60b3 pptpd[2140]: MGR: dropped small initial connection
Nov 22 12:21:23 sme60b3 pptpd[2140]: MGR: dropped small initial connection
Nov 22 12:25:41 sme60b3 pptpd[2140]: MGR: dropped small initial connection
Nov 22 12:29:54 sme60b3 pptpd[3018]: MGR: Launching /usr/sbin/pptpctrl to handle client
Nov 22 12:29:54 sme60b3 pptpd[3018]: CTRL: local address = 192.168.0.85
Nov 22 12:29:54 sme60b3 pptpd[3018]: CTRL: remote address = 192.168.0.247
Nov 22 12:29:54 sme60b3 pptpd[3018]: CTRL: pppd speed = 460800
Nov 22 12:29:54 sme60b3 pptpd[3018]: CTRL: pppd options file = /etc/ppp/options.pptpd
Nov 22 12:29:54 sme60b3 pptpd[3018]: CTRL: Client 216.177.2.40 control connection started
Nov 22 12:29:54 sme60b3 pptpd[3018]: CTRL: Received PPTP Control Message (type: 1)
Nov 22 12:29:54 sme60b3 pptpd[3018]: CTRL: Made a START CTRL CONN RPLY packet
Nov 22 12:29:54 sme60b3 pptpd[3018]: CTRL: I wrote 156 bytes to the client.
Nov 22 12:29:54 sme60b3 pptpd[3018]: CTRL: Sent packet to client
Nov 22 12:29:55 sme60b3 pptpd[3018]: CTRL: Received PPTP Control Message (type: 7)
Nov 22 12:29:55 sme60b3 pptpd[3018]: CTRL: Set parameters to 1525 maxbps, 64 window size
Nov 22 12:29:55 sme60b3 pptpd[3018]: CTRL: Made a OUT CALL RPLY packet
Nov 22 12:29:55 sme60b3 pptpd[3018]: CTRL: Starting call (launching pppd, opening GRE)
Nov 22 12:29:55 sme60b3 pptpd[3018]: CTRL: pty_fd = 5
Nov 22 12:29:55 sme60b3 pptpd[3018]: CTRL: tty_fd = 6
Nov 22 12:29:55 sme60b3 pptpd[3018]: CTRL: I wrote 32 bytes to the client.
Nov 22 12:29:55 sme60b3 pptpd[3018]: CTRL: Sent packet to client
Nov 22 12:29:55 sme60b3 pptpd[3019]: CTRL (PPPD Launcher): Connection speed = 460800
Nov 22 12:29:55 sme60b3 pptpd[3019]: CTRL (PPPD Launcher): local address = 192.168.0.85
Nov 22 12:29:55 sme60b3 pptpd[3019]: CTRL (PPPD Launcher): remote address = 192.168.0.247
Nov 22 12:29:55 sme60b3 pptpd[3018]: CTRL: Received PPTP Control Message (type: 15)
Nov 22 12:29:55 sme60b3 pptpd[3018]: CTRL: Got a SET LINK INFO packet with standard ACCMs
Nov 22 12:29:55 sme60b3 pptpd[3018]: GRE: Discarding duplicate packet
Nov 22 12:29:59 sme60b3 pptpd[3018]: CTRL: Received PPTP Control Message (type: 15)
Nov 22 12:29:59 sme60b3 pptpd[3018]: CTRL: Ignored a SET LINK INFO packet with real ACCMs!
Nov 22 12:30:05 sme60b3 e-smith[3082]: Processing event: ip-up.pptpd ppp0 /dev/pts/1 460800 192.168.0.85 192.168.0.247 pptpd
Nov 22 12:30:05 sme60b3 e-smith[3082]: Running event handler: /etc/e-smith/events/ip-up.pptpd/S70pptp-interface-access
Nov 22 12:30:05 sme60b3 /etc/e-smith/events/ip-up.pptpd/S70pptp-interface-access[3083]: /home/e-smith/configuration: OLD pptpd=service|Interfaces||StartIP|3232235767|sessions|4|status|enabled
Nov 22 12:30:05 sme60b3 /etc/e-smith/events/ip-up.pptpd/S70pptp-interface-access[3083]: /home/e-smith/configuration: NEW pptpd=service|Interfaces|ppp0|StartIP|3232235767|sessions|4|status|enabled
Nov 22 12:30:05 sme60b3 e-smith[3082]: S70pptp-interface-access=action|Event|ip-up.pptpd|Action|S70pptp-interface-access|Start|1069522205 82845|End|1069522205 367893|Elapsed|0.285048
Nov 22 12:30:05 sme60b3 e-smith[3082]: Running event handler: /etc/e-smith/events/ip-up.pptpd/S80conf-masq
Nov 22 12:30:06 sme60b3 e-smith[3082]:  at /etc/e-smith/events/ip-up.pptpd/S80conf-masq line 46
Nov 22 12:30:06 sme60b3 e-smith[3082]: S80conf-masq=action|Event|ip-up.pptpd|Action|S80conf-masq|Start|1069522205 368180|End|1069522206 347951|Elapsed|0.979771
Nov 22 12:30:06 sme60b3 e-smith[3082]: Running event handler: /etc/e-smith/events/ip-up.pptpd/S85adjust-masq
Nov 22 12:30:06 sme60b3 e-smith[3082]: S85adjust-masq=action|Event|ip-up.pptpd|Action|S85adjust-masq|Start|1069522206 348250|End|1069522206 514189|Elapsed|0.165939
Nov 22 12:30:06 sme60b3 ddclient: /etc/ppp/ddclient_ip-up.local ppp0 /dev/pts/1 460800 192.168.0.85 192.168.0.247 pptpd
Nov 22 12:30:12 sme60b3 pptpd[2140]: MGR: dropped small initial connection
Nov 22 12:34:35 sme60b3 pptpd[2140]: MGR: dropped small initial connection


Does anyone see anything that might point me in the direction of the disconnect problem I am having?

Thanks again,  great distro !!

[Jeff Peters]

I waited a few minutes later and have to add the following from the prior posted log file


Nov 22 12:36:41 sme60b3 pptpd[3018]: CTRL: Sending ECHO REQ id 1
Nov 22 12:36:41 sme60b3 pptpd[3018]: CTRL: Made a ECHO REQ packet
Nov 22 12:36:41 sme60b3 pptpd[3018]: CTRL: I wrote 16 bytes to the client.
Nov 22 12:36:41 sme60b3 pptpd[3018]: CTRL: Sent packet to client
Nov 22 12:37:25 sme60b3 pptpd[3018]: CTRL: Session timed out, ending call
Nov 22 12:37:25 sme60b3 pptpd[3018]: CTRL: Client 216.177.2.40 control connection finished
Nov 22 12:37:25 sme60b3 pptpd[3018]: CTRL: Exiting with active call
Nov 22 12:37:25 sme60b3 pptpd[3018]: CTRL: Made a CALL DISCONNECT RPLY packet
Nov 22 12:37:25 sme60b3 pptpd[3018]: CTRL: I wrote 148 bytes to the client.
Nov 22 12:37:25 sme60b3 pptpd[3018]: CTRL: Sent packet to client
Nov 22 12:37:25 sme60b3 pptpd[3018]: CTRL: Made a STOP CTRL REQ packet
Nov 22 12:37:25 sme60b3 pptpd[3018]: CTRL: I wrote 16 bytes to the client.
Nov 22 12:37:25 sme60b3 pptpd[3018]: CTRL: Sent packet to client
Nov 22 12:37:25 sme60b3 e-smith[3713]: Processing event: ip-down ppp0 /dev/pts/1 460800 192.168.0.85 192.168.0.247 pptpd
Nov 22 12:37:26 sme60b3 e-smith[3713]: Running event handler: /etc/e-smith/events/ip-down/S70pptp-interface-access
Nov 22 12:37:26 sme60b3 /etc/e-smith/events/ip-down/S70pptp-interface-access[3715]: /home/e-smith/configuration: OLD pptpd=service|Interfaces|ppp0|StartIP|3232235767|sessions|4|status|enabled
Nov 22 12:37:26 sme60b3 /etc/e-smith/events/ip-down/S70pptp-interface-access[3715]: /home/e-smith/configuration: NEW pptpd=service|Interfaces||StartIP|3232235767|sessions|4|status|enabled
Nov 22 12:37:26 sme60b3 e-smith[3713]: S70pptp-interface-access=action|Event|ip-down|Action|S70pptp-interface-access|Start|1069522646 121129|End|1069522646 351736|Elapsed|0.230607
Nov 22 12:37:30 sme60b3 pptpd[3018]: CTRL: Exiting now
Nov 22 12:37:30 sme60b3 pptpd[2140]: MGR: Reaped child 3018
Nov 22 12:38:55 sme60b3 pptpd[2140]: MGR: dropped small initial connection

Can I assume that the SME or the WinXP box timed out from this information?

[Ray Mitchell]

Do a search on VPN (all dates). You will find lots of posts about this.
Regs
Ray

[Jeff Peters]

Thanks kindly for your reply Ray. I'd gone through page after page of the search results.

Anyway, I think I finally fixed the problem by removing the VPN client on my XP box and restarting a new one and it worked. The PPTP connects to my SME box and stays connected.