[pptp-server] PoPToP problems under OpenBSD 2.8

[Andre Dalle]

I followed the guide for FreeBSD, recompiled my kernel without GRE, but logins
from 98 fail right away.

You'll notice my configs are almost identical to the samples at:
http://heyer.supranet.net/pptp/

PoPToP version is 1.0.1 compiled with the bsd-ppp and with-ip-alloc options.

Here are the pptpd/pppd SYSLOG messages, and my configs.  Maybe someone can
decode the syslog messages better than myself..

/etc/pptpd.conf:
speed 115200
option /etc/ppp/ppp.conf
debug
localip 10.0.254.200
remoteip 10.0.254.201-210
pidfile /var/run/pptpd.pid

/etc/ppp.conf:
loop:
 set timeout 0
 set log phase chat connect lcp ipcp command
 set device localhost:pptp
 set dial
 set login
 # Server (local) IP address, Range for Clients, and Netmask
 set ifaddr 10.0.254.200 10.0.254.201-10.0.254.210 255.255.255.255
 set server /tmp/loop "" 0177

loop-in:
 set timeout 0
 set log phase lcp ipcp command
 allow mode direct

pptp:
 load loop
 enable chap
 disable pap
 # Authenticate against /etc/passwd
 #enable passwdauth
 enable proxy
 accept dns
 # DNS Servers to assign client
 set dns 10.0.254.1
 # NetBIOS/WINS Servers to assign client
 set nbns 10.0.254.2
 set device !/etc/ppp/secure

/etc/ppp/ppp.secret:
dallea  x       *
dave    x       *

/etc/ppp/secure:
#!/bin/sh
exec /usr/sbin/ppp -direct loop-in

/etc/ppp/options:
lock
auth
#usehostname


And finally, the SYSLOG messages:
It seems like a lot of messages are duplicated.. I don't know why that is.

May 13 17:33:09 waldorf pptpd[18491]: MGR: Manager process started
May 13 17:33:09 waldorf pptpd[18491]: MGR: Manager process started
May 13 17:33:14 waldorf pptpd[13804]: MGR: Launching /usr/local/sbin/pptpctrl
to handle client
May 13 17:33:14 waldorf pptpd[13804]: CTRL: pppd speed = 115200
May 13 17:33:14 waldorf pptpd[13804]: CTRL: pppd options file =
/etc/ppp/options
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Client 24.42.151.183 control
connection started
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Client 24.42.151.183 control
connection started
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Received PPTP Control Message
(type: 1)
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Made a START CTRL CONN RPLY packet
May 13 17:33:14 waldorf pptpd[13804]: CTRL: I wrote 156 bytes to the client.
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Sent packet to client
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Received PPTP Control Message
(type: 7)
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Set parameters to 0 maxbps, 16
window size
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Made a OUT CALL RPLY packet
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Starting call (launching pppd,
opening GRE)
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Starting call (launching pppd,
opening GRE)
May 13 17:33:14 waldorf pptpd[13804]: CTRL: pty_fd = 6
May 13 17:33:14 waldorf pptpd[13804]: CTRL: tty_fd = 5
May 13 17:33:14 waldorf pptpd[13804]: CTRL: I wrote 32 bytes to the client.
May 13 17:33:14 waldorf ppp[27611]: Phase: Using interface: tun0
May 13 17:33:14 waldorf ppp[27611]: Phase: Using interface: tun0
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Sent packet to client
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: Created in closed state
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: Created in closed state
May 13 17:33:14 waldorf ppp[27611]: Command: loop: set device localhost:pptp
May 13 17:33:14 waldorf ppp[27611]: Command: loop: set device localhost:pptp
May 13 17:33:14 waldorf ppp[27611]: Command: loop: set dial
May 13 17:33:14 waldorf ppp[27611]: Command: loop: set dial
May 13 17:33:14 waldorf ppp[27611]: Command: loop: set login
May 13 17:33:14 waldorf ppp[27611]: Command: loop: set login
May 13 17:33:14 waldorf ppp[27611]: Command: loop: set ifaddr 10.0.254.200
10.0.254.201-10.0.254.210 255.255.255.255
May 13 17:33:14 waldorf ppp[27611]: Command: loop: set ifaddr 10.0.254.200
10.0.254.201-10.0.254.210 255.255.255.255
May 13 17:33:14 waldorf ppp[27611]: IPCP: Selected IP address 10.0.254.202
May 13 17:33:14 waldorf ppp[27611]: IPCP: Selected IP address 10.0.254.202
May 13 17:33:14 waldorf ppp[27611]: Command: loop: set server /tmp/loop
******** 0177
May 13 17:33:14 waldorf ppp[27611]: Command: loop: set server /tmp/loop
******** 0177
May 13 17:33:14 waldorf ppp[27611]: Phase: Listening at local socket
/tmp/loop.
May 13 17:33:14 waldorf ppp[27611]: Phase: Listening at local socket
/tmp/loop.
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: enable chap
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: enable chap
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: disable pap
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: disable pap
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: enable proxy
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: enable proxy
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: accept dns
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: accept dns
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: set dns 10.0.254.1
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: set dns 10.0.254.1
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: set nbns 10.0.254.2
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: set nbns 10.0.254.2
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: set device !/etc/ppp/secure
May 13 17:33:14 waldorf ppp[27611]: Command: pptp: set device !/etc/ppp/secure
May 13 17:33:14 waldorf ppp[27611]: Phase: PPP Started (direct mode).
May 13 17:33:14 waldorf ppp[27611]: Phase: PPP Started (direct mode).
May 13 17:33:14 waldorf ppp[27611]: Phase: bundle: Establish
May 13 17:33:14 waldorf ppp[27611]: Phase: bundle: Establish
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: closed -> opening
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: closed -> opening
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: Connected!
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: Connected!
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: opening -> carrier
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: opening -> carrier
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: carrier -> lcp
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: carrier -> lcp
May 13 17:33:14 waldorf ppp[27611]: LCP: FSM: Using "deflink" as a transport
May 13 17:33:14 waldorf ppp[27611]: LCP: FSM: Using "deflink" as a transport
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: State change Initial -->
Closed
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: State change Initial -->
Closed
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: State change Closed -->
Stopped
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: State change Closed -->
Stopped
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: RecvConfigReq(1) state =
Stopped
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: RecvConfigReq(1) state =
Stopped
May 13 17:33:14 waldorf ppp[27611]: LCP:  MAGICNUM[6] 0x001e236c
May 13 17:33:14 waldorf ppp[27611]: LCP:  MAGICNUM[6] 0x001e236c
May 13 17:33:14 waldorf ppp[27611]: LCP:  PROTOCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP:  PROTOCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP:  ACFCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP:  ACFCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: SendConfigReq(1) state =
Stopped
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: SendConfigReq(1) state =
Stopped
May 13 17:33:14 waldorf ppp[27611]: LCP:  ACFCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP:  ACFCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP:  PROTOCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP:  PROTOCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP:  ACCMAP[6] 0x00000000
May 13 17:33:14 waldorf ppp[27611]: LCP:  ACCMAP[6] 0x00000000
May 13 17:33:14 waldorf ppp[27611]: LCP:  MRU[4] 1500
May 13 17:33:14 waldorf ppp[27611]: LCP:  MRU[4] 1500
May 13 17:33:14 waldorf ppp[27611]: LCP:  MAGICNUM[6] 0x6fbdc413
May 13 17:33:14 waldorf ppp[27611]: LCP:  MAGICNUM[6] 0x6fbdc413
May 13 17:33:14 waldorf ppp[27611]: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05)
May 13 17:33:14 waldorf ppp[27611]: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05)
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: SendConfigAck(1) state =
Stopped
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: SendConfigAck(1) state =
Stopped
May 13 17:33:14 waldorf ppp[27611]: LCP:  MAGICNUM[6] 0x001e236c
May 13 17:33:14 waldorf ppp[27611]: LCP:  MAGICNUM[6] 0x001e236c
May 13 17:33:14 waldorf ppp[27611]: LCP:  PROTOCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP:  PROTOCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP:  ACFCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP:  ACFCOMP[2]
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: LayerStart
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: LayerStart
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: State change Stopped -->
Ack-Sent
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: State change Stopped -->
Ack-Sent
May 13 17:33:14 waldorf pptpd[13804]: GRE: xmit failed from decaps_hdlc: No
route to host
May 13 17:33:14 waldorf pptpd[13804]: GRE: xmit failed from decaps_hdlc: No
route to host
May 13 17:33:14 waldorf pptpd[13804]: CTRL: PTY read or GRE write failed
(pty,gre)=(6,5)
May 13 17:33:14 waldorf pptpd[13804]: CTRL: PTY read or GRE write failed
(pty,gre)=(6,5)
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Client 24.42.151.183 control
connection finished
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Client 24.42.151.183 control
connection finished
May 13 17:33:14 waldorf pptpd[13804]: CTRL: Exiting now
May 13 17:33:14 waldorf pptpd[18491]: MGR: Reaped child 13804
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: read (0): Got zero bytes
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: read (0): Got zero bytes
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: State change Ack-Sent -->
Starting
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: State change Ack-Sent -->
Starting
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: LayerFinish
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: LayerFinish
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: State change Starting -->
Initial
May 13 17:33:14 waldorf ppp[27611]: LCP: deflink: State change Starting -->
Initial
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: Disconnected!
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: Disconnected!
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: Connect time: 0 secs: 35
octets in, 97 octets out
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: Connect time: 0 secs: 35
octets in, 97 octets out
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: : 1 packets in, 2 packets
out
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: : 1 packets in, 2 packets
out
May 13 17:33:14 waldorf ppp[27611]: Phase:  total 132 bytes/sec, peak 0
bytes/sec on Sun May 13 17:33:14 2001
May 13 17:33:14 waldorf ppp[27611]: Phase:  total 132 bytes/sec, peak 0
bytes/sec on Sun May 13 17:33:14 2001
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: lcp -> closed
May 13 17:33:14 waldorf ppp[27611]: Phase: deflink: lcp -> closed
May 13 17:33:14 waldorf ppp[27611]: Phase: bundle: Dead
May 13 17:33:14 waldorf ppp[27611]: Phase: bundle: Dead
May 13 17:33:14 waldorf ppp[27611]: Phase: PPP Terminated (normal).
May 13 17:33:14 waldorf ppp[27611]: Phase: PPP Terminated (normal).
May 13 17:33:14 waldorf ppp[27611]: Phase: Found interface rl1 for
10.0.254.202
May 13 17:33:14 waldorf ppp[27611]: Phase: Found interface rl1 for
10.0.254.202

 

-- 
Andre Dalle			[adalle at ncf.ca]
Systems Administrator,
National Capital Freenet	[http://www.ncf.ca]