[pptp-server] OpenBSD 2.7 pptpd strange GRE errors

Detelin Batchovski d_batchovski at softhome.net
Fri Oct 6 10:19:31 CDT 2000 

Hello everyone,
I have troubles with OpenBSD 2.7 and PoPToP v1.0.1 & PoPToP v1.0.0.
pptpd compiled with "--with-bsdppp --with-pppd-ip-alloc".
Win2k return error: "Error 619:The specified port is not connected."
I can't understand what caused this:

pptpd[19079]: GRE: read(fd=5,buffer=6544,len=8196) from PTY failed: status =
0 error = No error
Oct  6 17:56:42 obsd ppp[28405]: tun0: Phase: deflink: Connect time: 17
secs: 0 octets in, 320 octets out
Oct  6 17:56:42 obsd pptpd[19079]: CTRL: PTY read or GRE write failed
(pty,gre)=(5,4)

I try to make VPN connections from Win98 and Win2k, but result is equal.

Anyone can help me ?

Here is log file:

Oct  6 17:56:25 obsd pptpd[19079]: MGR: Launching /usr/local/sbin/pptpctrl
to handle client
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: pppd speed = 1000000
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: pppd options file =
/etc/ppp/options
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Client 10.0.0.3 control connection
started
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Received PPTP Control Message
(type: 1)
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Made a START CTRL CONN RPLY packet
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: I wrote 156 bytes to the client.
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Sent packet to client
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Received PPTP Control Message
(type: 7)
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Set parameters to 1525 maxbps, 64
window size
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Made a OUT CALL RPLY packet
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Starting call (launching pppd,
opening GRE)
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: pty_fd = 5
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: tty_fd = 4
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: I wrote 32 bytes to the client.
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Sent packet to client
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Received PPTP Control Message
(type: 15)
Oct  6 17:56:25 obsd pptpd[19079]: CTRL: Got a SET LINK INFO packet with
standard ACCMs
Oct  6 17:56:25 obsd ppp[28405]: Phase: Using interface: tun0
Oct  6 17:56:25 obsd ppp[28405]: Phase: deflink: Created in closed state
Oct  6 17:56:25 obsd ppp[28405]: Warning: device=/dev/pty0: Invalid command
Oct  6 17:56:25 obsd ppp[28405]: Warning: device=/dev/pty0: Failed 1
Oct  6 17:56:25 obsd ppp[28405]: tun0: Command: default: set speed 115200
Oct  6 17:56:25 obsd ppp[28405]: tun0: Command: pptp: enable chap
Oct  6 17:56:25 obsd ppp[28405]: tun0: Command: pptp: enable proxy
Oct  6 17:56:25 obsd ppp[28405]: tun0: Command: pptp: set ifaddr 10.0.0.1
10.0.0.240 255.255.255.255
Oct  6 17:56:25 obsd ppp[28405]: tun0: Phase: PPP Started (direct mode).
Oct  6 17:56:25 obsd ppp[28405]: tun0: Phase: bundle: Establish
Oct  6 17:56:25 obsd ppp[28405]: tun0: Phase: deflink: closed -> opening
Oct  6 17:56:25 obsd ppp[28405]: tun0: Phase: deflink: Connected!
Oct  6 17:56:25 obsd ppp[28405]: tun0: Phase: deflink: opening -> carrier
Oct  6 17:56:25 obsd ppp[28405]: tun0: Phase: deflink: carrier -> lcp
Oct  6 17:56:25 obsd ppp[28405]: tun0: LCP: FSM: Using "deflink" as a
transport
Oct  6 17:56:25 obsd ppp[28405]: tun0: LCP: deflink: State change
Initial --> Closed
Oct  6 17:56:25 obsd ppp[28405]: tun0: LCP: deflink: State change Closed -->
Stopped
Oct  6 17:56:26 obsd ppp[28405]: tun0: LCP: deflink: LayerStart
Oct  6 17:56:26 obsd ppp[28405]: tun0: LCP: deflink: SendConfigReq(1) state
= Stopped
Oct  6 17:56:26 obsd ppp[28405]: tun0: LCP:  ACFCOMP[2]
Oct  6 17:56:26 obsd ppp[28405]: tun0: LCP:  PROTOCOMP[2]
Oct  6 17:56:26 obsd ppp[28405]: tun0: LCP:  ACCMAP[6] 0x00000000
Oct  6 17:56:26 obsd ppp[28405]: tun0: LCP:  MRU[4] 1500
Oct  6 17:56:26 obsd ppp[28405]: tun0: LCP:  MAGICNUM[6] 0x0f1806ae
Oct  6 17:56:26 obsd ppp[28405]: tun0: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05)
Oct  6 17:56:26 obsd ppp[28405]: tun0: LCP: deflink: State change
Stopped --> Req-Sent
Oct  6 17:56:29 obsd ppp[28405]: tun0: LCP: deflink: SendConfigReq(1) state
= Req-Sent
Oct  6 17:56:29 obsd ppp[28405]: tun0: LCP:  ACFCOMP[2]
Oct  6 17:56:29 obsd ppp[28405]: tun0: LCP:  PROTOCOMP[2]
Oct  6 17:56:29 obsd ppp[28405]: tun0: LCP:  ACCMAP[6] 0x00000000
Oct  6 17:56:29 obsd ppp[28405]: tun0: LCP:  MRU[4] 1500
Oct  6 17:56:29 obsd ppp[28405]: tun0: LCP:  MAGICNUM[6] 0x0f1806ae
Oct  6 17:56:29 obsd ppp[28405]: tun0: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05)
Oct  6 17:56:32 obsd ppp[28405]: tun0: LCP: deflink: SendConfigReq(1) state
= Req-Sent
Oct  6 17:56:32 obsd ppp[28405]: tun0: LCP:  ACFCOMP[2]
Oct  6 17:56:32 obsd ppp[28405]: tun0: LCP:  PROTOCOMP[2]
Oct  6 17:56:32 obsd ppp[28405]: tun0: LCP:  ACCMAP[6] 0x00000000
Oct  6 17:56:32 obsd ppp[28405]: tun0: LCP:  MRU[4] 1500
Oct  6 17:56:32 obsd ppp[28405]: tun0: LCP:  MAGICNUM[6] 0x0f1806ae
Oct  6 17:56:32 obsd ppp[28405]: tun0: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05)
Oct  6 17:56:35 obsd ppp[28405]: tun0: LCP: deflink: SendConfigReq(1) state
= Req-Sent
Oct  6 17:56:35 obsd ppp[28405]: tun0: LCP:  ACFCOMP[2]
Oct  6 17:56:35 obsd ppp[28405]: tun0: LCP:  PROTOCOMP[2]
Oct  6 17:56:35 obsd ppp[28405]: tun0: LCP:  ACCMAP[6] 0x00000000
Oct  6 17:56:35 obsd ppp[28405]: tun0: LCP:  MRU[4] 1500
Oct  6 17:56:35 obsd ppp[28405]: tun0: LCP:  MAGICNUM[6] 0x0f1806ae
Oct  6 17:56:35 obsd ppp[28405]: tun0: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05)
Oct  6 17:56:39 obsd ppp[28405]: tun0: LCP: deflink: SendConfigReq(1) state
= Req-Sent
Oct  6 17:56:39 obsd ppp[28405]: tun0: LCP:  ACFCOMP[2]
Oct  6 17:56:39 obsd ppp[28405]: tun0: LCP:  PROTOCOMP[2]
Oct  6 17:56:39 obsd ppp[28405]: tun0: LCP:  ACCMAP[6] 0x00000000
Oct  6 17:56:39 obsd ppp[28405]: tun0: LCP:  MRU[4] 1500
Oct  6 17:56:39 obsd ppp[28405]: tun0: LCP:  MAGICNUM[6] 0x0f1806ae
Oct  6 17:56:39 obsd ppp[28405]: tun0: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05)
Oct  6 17:56:42 obsd ppp[28405]: tun0: LCP: deflink: LayerFinish
Oct  6 17:56:42 obsd ppp[28405]: tun0: LCP: deflink: State change
Req-Sent --> Stopped
Oct  6 17:56:42 obsd ppp[28405]: tun0: LCP: deflink: State change
Stopped --> Closed
Oct  6 17:56:42 obsd ppp[28405]: tun0: LCP: deflink: State change Closed -->
Initial
Oct  6 17:56:42 obsd ppp[28405]: tun0: Phase: deflink: Disconnected!
Oct  6 17:56:42 obsd pptpd[19079]: GRE: read(fd=5,buffer=6544,len=8196) from
PTY failed: status = 0 error = No error
Oct  6 17:56:42 obsd ppp[28405]: tun0: Phase: deflink: Connect time: 17
secs: 0 octets in, 320 octets out
Oct  6 17:56:42 obsd pptpd[19079]: CTRL: PTY read or GRE write failed
(pty,gre)=(5,4)
Oct  6 17:56:42 obsd ppp[28405]: tun0: Phase:  total 18 bytes/sec, peak 25
bytes/sec on Fri Oct  6 17:56:29 2000
Oct  6 17:56:42 obsd pptpd[19079]: CTRL: Client 10.0.0.3 control connection
finished
Oct  6 17:56:42 obsd ppp[28405]: tun0: Phase: deflink: lcp -> closed
Oct  6 17:56:42 obsd pptpd[19079]: CTRL: Exiting now
Oct  6 17:56:42 obsd ppp[28405]: tun0: Phase: bundle: Dead
Oct  6 17:56:42 obsd ppp[28405]: tun0: Phase: PPP Terminated (normal).
Oct  6 17:56:42 obsd pptpd[1167]: MGR: Reaped child 19079

Here is Win2k log file:

[1308] 18:10:30:375: PPPEMSG_Start recvd, d=,
hPort=5,callback=0,mask=1a30108,IfType=-1
[348] 18:10:30:375: Line up event occurred on port 5
[348] 18:10:30:375: Local identification = MSRAS-1-SERVER2K
[348] 18:10:30:375: PortName: VPN4-4
[348] 18:10:30:375: Starting PPP on link with
IfType=0xffffffff,IPIf=0xffffffff,IPXIf=0xffffffff
[348] 18:10:30:375: RasGetBuffer returned de060 for SendBuf
[348] 18:10:30:375: FsmInit called for protocol = c021, port = 5
[348] 18:10:30:375: ConfigInfo = 1a30108
[348] 18:10:30:375: APs available = 4e
[348] 18:10:30:375: FsmReset called for protocol = c021, port = 5
[348] 18:10:30:375: Inserting port in bucket # 5
[348] 18:10:30:375: Inserting bundle in bucket # 2
[348] 18:10:30:375: FsmOpen event received for protocol c021 on port 5
[348] 18:10:30:375: FsmThisLayerStarted called for protocol = c021, port = 5
[348] 18:10:30:375: FsmUp event received for protocol c021 on port 5
[348] 18:10:30:375: <PPP packet sent at 10/06/2000 15:10:30:375
[348] 18:10:30:375: <Protocol = LCP, Type = Configure-Req, Length = 0x10, Id
= 0x0, Port = 5
[348] 18:10:30:375: <C0 21 01 00 00 0E 05 06 02 50 0C 40 07 02 08 02
|.!.......P. at ....|
[348] 18:10:30:375:
[348] 18:10:30:375: InsertInTimerQ called
portid=26,Id=0,Protocol=c021,EventType=0,fAuth=0
[348] 18:10:30:375: InsertInTimerQ called
portid=26,Id=0,Protocol=0,EventType=3,fAuth=0
[1108] 18:10:31:750: Packet received (31 bytes) for hPort 5
[348] 18:10:31:750: >PPP packet received at 10/06/2000 15:10:31:750
[348] 18:10:31:750: >Protocol = LCP, Type = Configure-Req, Length = 0x1f, Id
= 0x1, Port = 5
[348] 18:10:31:750: >C0 21 01 01 00 1D 08 02 07 02 02 06 00 00 00 00
|.!..............|
[348] 18:10:31:750: >01 04 05 DC 05 06 24 E7 9D 3C 03 05 C2 23 05 00
|......$..<...#..|
[348] 18:10:31:750:
[348] 18:10:31:750: <PPP packet sent at 10/06/2000 15:10:31:750
[348] 18:10:31:750: <Protocol = LCP, Type = Configure-Ack, Length = 0x1f, Id
= 0x1, Port = 5
[348] 18:10:31:750: <C0 21 02 01 00 1D 08 02 07 02 02 06 00 00 00 00
|.!..............|
[348] 18:10:31:750: <01 04 05 DC 05 06 24 E7 9D 3C 03 05 C2 23 05 00
|......$..<...#..|
[348] 18:10:31:750:
[348] 18:10:32:375: Recv timeout event received for
portid=26,Id=0,Protocol=c021,fAuth=0
[348] 18:10:32:375: <PPP packet sent at 10/06/2000 15:10:32:375
[348] 18:10:32:375: <Protocol = LCP, Type = Configure-Req, Length = 0x10, Id
= 0x1, Port = 5
[348] 18:10:32:375: <C0 21 01 01 00 0E 05 06 02 50 0C 40 07 02 08 02
|.!.......P. at ....|
[348] 18:10:32:375:
[348] 18:10:32:375: InsertInTimerQ called
portid=26,Id=1,Protocol=c021,EventType=0,fAuth=0
[1108] 18:10:34:734: Packet received (31 bytes) for hPort 5
[348] 18:10:34:734: >PPP packet received at 10/06/2000 15:10:34:734
[348] 18:10:34:734: >Protocol = LCP, Type = Configure-Req, Length = 0x1f, Id
= 0x1, Port = 5
[348] 18:10:34:734: >C0 21 01 01 00 1D 08 02 07 02 02 06 00 00 00 00
|.!..............|
[348] 18:10:34:734: >01 04 05 DC 05 06 24 E7 9D 3C 03 05 C2 23 05 00
|......$..<...#..|
[348] 18:10:34:734:
[348] 18:10:34:734: <PPP packet sent at 10/06/2000 15:10:34:734
[348] 18:10:34:734: <Protocol = LCP, Type = Configure-Ack, Length = 0x1f, Id
= 0x1, Port = 5
[348] 18:10:34:734: <C0 21 02 01 00 1D 08 02 07 02 02 06 00 00 00 00
|.!..............|
[348] 18:10:34:734: <01 04 05 DC 05 06 24 E7 9D 3C 03 05 C2 23 05 00
|......$..<...#..|
[348] 18:10:34:734:
[348] 18:10:35:390: Recv timeout event received for
portid=26,Id=1,Protocol=c021,fAuth=0
[348] 18:10:35:390: <PPP packet sent at 10/06/2000 15:10:35:390
[348] 18:10:35:390: <Protocol = LCP, Type = Configure-Req, Length = 0x10, Id
= 0x2, Port = 5
[348] 18:10:35:390: <C0 21 01 02 00 0E 05 06 02 50 0C 40 07 02 08 02
|.!.......P. at ....|
[348] 18:10:35:390:
[348] 18:10:35:390: InsertInTimerQ called
portid=26,Id=2,Protocol=c021,EventType=0,fAuth=0
[1108] 18:10:37:750: Packet received (31 bytes) for hPort 5
[348] 18:10:37:750: >PPP packet received at 10/06/2000 15:10:37:750
[348] 18:10:37:750: >Protocol = LCP, Type = Configure-Req, Length = 0x1f, Id
= 0x1, Port = 5
[348] 18:10:37:750: >C0 21 01 01 00 1D 08 02 07 02 02 06 00 00 00 00
|.!..............|
[348] 18:10:37:750: >01 04 05 DC 05 06 24 E7 9D 3C 03 05 C2 23 05 00
|......$..<...#..|
[348] 18:10:37:750:
[348] 18:10:37:750: <PPP packet sent at 10/06/2000 15:10:37:750
[348] 18:10:37:750: <Protocol = LCP, Type = Configure-Ack, Length = 0x1f, Id
= 0x1, Port = 5
[348] 18:10:37:750: <C0 21 02 01 00 1D 08 02 07 02 02 06 00 00 00 00
|.!..............|
[348] 18:10:37:750: <01 04 05 DC 05 06 24 E7 9D 3C 03 05 C2 23 05 00
|......$..<...#..|
[348] 18:10:37:750:
[348] 18:10:39:390: Recv timeout event received for
portid=26,Id=2,Protocol=c021,fAuth=0
[348] 18:10:39:390: <PPP packet sent at 10/06/2000 15:10:39:390
[348] 18:10:39:390: <Protocol = LCP, Type = Configure-Req, Length = 0x10, Id
= 0x3, Port = 5
[348] 18:10:39:390: <C0 21 01 03 00 0E 05 06 02 50 0C 40 07 02 08 02
|.!.......P. at ....|
[348] 18:10:39:390:
[348] 18:10:39:390: InsertInTimerQ called
portid=26,Id=3,Protocol=c021,EventType=0,fAuth=0
[1108] 18:10:40:765: Packet received (31 bytes) for hPort 5
[348] 18:10:40:765: >PPP packet received at 10/06/2000 15:10:40:765
[348] 18:10:40:765: >Protocol = LCP, Type = Configure-Req, Length = 0x1f, Id
= 0x1, Port = 5
[348] 18:10:40:765: >C0 21 01 01 00 1D 08 02 07 02 02 06 00 00 00 00
|.!..............|
[348] 18:10:40:765: >01 04 05 DC 05 06 24 E7 9D 3C 03 05 C2 23 05 00
|......$..<...#..|
[348] 18:10:40:765:
[348] 18:10:40:765: <PPP packet sent at 10/06/2000 15:10:40:765
[348] 18:10:40:765: <Protocol = LCP, Type = Configure-Ack, Length = 0x1f, Id
= 0x1, Port = 5
[348] 18:10:40:765: <C0 21 02 01 00 1D 08 02 07 02 02 06 00 00 00 00
|.!..............|
[348] 18:10:40:765: <01 04 05 DC 05 06 24 E7 9D 3C 03 05 C2 23 05 00
|......$..<...#..|
[348] 18:10:40:765:
[348] 18:10:43:390: Recv timeout event received for
portid=26,Id=3,Protocol=c021,fAuth=0
[348] 18:10:43:390: <PPP packet sent at 10/06/2000 15:10:43:390
[348] 18:10:43:390: <Protocol = LCP, Type = Configure-Req, Length = 0x10, Id
= 0x4, Port = 5
[348] 18:10:43:390: <C0 21 01 04 00 0E 05 06 02 50 0C 40 07 02 08 02
|.!.......P. at ....|
[348] 18:10:43:390:
[348] 18:10:43:390: InsertInTimerQ called
portid=26,Id=4,Protocol=c021,EventType=0,fAuth=0
[1108] 18:10:43:781: Packet received (31 bytes) for hPort 5
[348] 18:10:43:796: >PPP packet received at 10/06/2000 15:10:43:796
[348] 18:10:43:796: >Protocol = LCP, Type = Configure-Req, Length = 0x1f, Id
= 0x1, Port = 5
[348] 18:10:43:796: >C0 21 01 01 00 1D 08 02 07 02 02 06 00 00 00 00
|.!..............|
[348] 18:10:43:796: >01 04 05 DC 05 06 24 E7 9D 3C 03 05 C2 23 05 00
|......$..<...#..|
[348] 18:10:43:796:
[348] 18:10:43:796: <PPP packet sent at 10/06/2000 15:10:43:796
[348] 18:10:43:796: <Protocol = LCP, Type = Configure-Ack, Length = 0x1f, Id
= 0x1, Port = 5
[348] 18:10:43:796: <C0 21 02 01 00 1D 08 02 07 02 02 06 00 00 00 00
|.!..............|
[348] 18:10:43:796: <01 04 05 DC 05 06 24 E7 9D 3C 03 05 C2 23 05 00
|......$..<...#..|
[348] 18:10:43:796:
[1108] 18:10:46:843: PPPEMSG_LineDown recvd, hPort=5

[348] 18:10:46:859: Line down event occurred on port 5
[348] 18:10:46:890: FsmDown event received for protocol c021 on port 5
[348] 18:10:46:890: RemoveFromTimerQ called
portid=26,Id=4,Protocol=c021,EventType=0,fAuth=0
[348] 18:10:46:890: FsmReset called for protocol = c021, port = 5
[348] 18:10:46:890: RemoveFromTimerQ called
portid=26,Id=0,Protocol=0,EventType=3,fAuth=0
[348] 18:10:46:890: RemoveFromTimerQ called
portid=26,Id=0,Protocol=0,EventType=1,fAuth=0
[348] 18:10:46:890: RemoveFromTimerQ called
portid=26,Id=0,Protocol=c029,EventType=0,fAuth=0
[348] 18:10:46:890: LcpEnd
[348] 18:10:46:890: NotifyCaller(hPort=5, dwMsgId=23)
[348] 18:10:46:890: NotifyCaller(hPort=5, dwMsgId=10)

Very sorry about my big mail.

Best regards.
Detelin

More information about the pptp-server mailing list