[pptp-server] OpenBSD 2.7 pptpd strange GRE errors

[Marc Charbonneau]

>Oct  6 17:56:42 obsd pptpd[19079]: GRE: read(fd=5,buffer=6544,len=8196)
from PTY failed: status = 0 error = No error
It looks like your firewall is blocking input of protocol GRE (47).

>Oct  6 17:56:42 obsd pptpd[19079]: CTRL: PTY read or GRE write failed
(pty,gre)=(5,4)
And it also block output of protocol GRE (47).

You have to allow that proto for input and output

----- Original Message -----
From: Detelin Batchovski <d_batchovski at softhome.net>
To: <pptp-server at lists.schulte.org>
Sent: Friday, October 06, 2000 11:19 AM
Subject: [pptp-server] OpenBSD 2.7 pptpd strange GRE errors


> 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
>
>
> _______________________________________________
> pptp-server maillist  -  pptp-server at lists.schulte.org
> http://lists.schulte.org/mailman/listinfo/pptp-server
> List services provided by www.schulteconsulting.com!