Date: Wed, 19 Jun 2002 19:01:59 -0400 From: Mike Tancsa <mike@sentex.net> To: Brian Somers <brian@Awfulhak.org> Cc: freebsd-net@FreeBSD.ORG Subject: Re: FreeBSD PPPoE Broken ? (was Re: tracking down strange MTU issues with PPPoE) Message-ID: <5.1.0.14.0.20020619185445.031f0928@192.168.0.12> In-Reply-To: <20020619224229.55be2f1d.brian@Awfulhak.org> References: <5.1.0.14.0.20020619153843.04ac1868@marble.sentex.ca> <5.1.0.14.0.20020618203201.07212f30@192.168.0.12> <5.1.0.14.0.20020618163928.05018cf0@marble.sentex.ca> <5.1.0.14.0.20020618163928.05018cf0@marble.sentex.ca> <5.1.0.14.0.20020618203201.07212f30@192.168.0.12> <5.1.0.14.0.20020619153843.04ac1868@marble.sentex.ca>
next in thread | previous in thread | raw e-mail | index | archive | help
Thanks, here you go!
Jun 19 18:56:23 iscar ppp[55]: tun0: LCP: deflink: RecvEchoReply(41) state
= Opened
Jun 19 18:57:28 iscar ppp[55]: tun0: Phase: Received NGM_PPPOE_ACNAME (hook
"bas8-toronto63")
Jun 19 18:57:29 iscar ppp[55]: tun0: Phase: Received NGM_PPPOE_<11> (hook
"+^K^H^Hh^P^K^H")
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: Received NGM_PPPOE_SUCCESS
(hook "tun0")
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: deflink: carrier -> login
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: deflink: login -> lcp
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: FSM: Using "deflink" as a transport
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: State change Initial -->
Closed
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: State change Closed -->
Stopped
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigReq(58) state
= Stopped
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP)
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0x3cc22f0d
Jun 19 18:57:30 iscar ppp[55]: tun0: Warning: deflink: Reducing configured
MRU from 1500 to 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigReq(1) state =
Stopped
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xada0b92c
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 5000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigAck(58) state
= Stopped
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP)
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0x3cc22f0d
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: LayerStart
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: State change Stopped -->
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigRej(1) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: Sending ident magic ada0b92c text
user-ppp 2.3.3 (built Jun 18 2002)
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendIdent(0) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 5000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigReq(2) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xada0b92c
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigAck(2) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: State change Ack-Sent
--> Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: LayerUp
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendEchoRequest(0) state
= Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: Sending ident magic ada0b92c text
user-ppp 2.3.3 (built Jun 18 2002)
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendIdent(1) state = Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: bundle: Authenticate
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: deflink: his = PAP, mine = none
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: Pap Output: iscar@sentex.ca
********
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvEchoReply(0) state =
Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigReq(1) state =
Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: LayerDown
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: LayerDown
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP)
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xf6666b1e
Jun 19 18:57:30 iscar ppp[55]: tun0: Warning: deflink: Reducing configured
MRU from 1500 to 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigReq(3) state =
Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xc0fa0be2
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 5000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigAck(1) state =
Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP)
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xf6666b1e
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: State change Opened -->
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigNak(3) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 10000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigReq(4) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xc0fa0be2
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 5000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigNak(4) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 10000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigReq(5) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xc0fa0be2
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 5000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigNak(5) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 10000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigReq(6) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xc0fa0be2
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 5000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigNak(6) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 10000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigReq(7) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xc0fa0be2
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 5000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigNak(7) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 10000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigReq(8) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xc0fa0be2
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 5000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigRej(8) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: Sending ident magic c0fa0be2 text
user-ppp 2.3.3 (built Jun 18 2002)
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendIdent(2) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: QUALPROTO[8] proto c025,
interval 5000ms
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendConfigReq(9) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MRU[4] 1492
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: MAGICNUM[6] 0xc0fa0be2
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvConfigAck(9) state =
Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: State change Ack-Sent
--> Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: LayerUp
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendEchoRequest(0) state
= Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: Sending ident magic c0fa0be2 text
user-ppp 2.3.3 (built Jun 18 2002)
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: SendIdent(3) state = Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: deflink: his = PAP, mine = none
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: Pap Output: iscar@sentex.ca
********
Jun 19 18:57:30 iscar ppp[55]: tun0: LCP: deflink: RecvEchoReply(0) state =
Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: Pap Input: SUCCESS ()
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: Using trigger address 0.0.0.0
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: deflink: lcp -> open
Jun 19 18:57:30 iscar ppp[55]: tun0: Phase: bundle: Network
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: FSM: Using "deflink" as a transport
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: State change Initial
--> Closed
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: LayerStart.
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: SendConfigReq(1) state
= Closed
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: IPADDR[6] 0.0.0.0
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with
slot compression
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: PRIDNS[6] 199.212.134.11
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: SECDNS[6] 64.7.128.99
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: State change Closed -->
Req-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: RecvConfigReq(1) state
= Req-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: COMPPROTO[6] 16 VJ slots
without slot compression
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: IPADDR[6] 64.7.134.129
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: SendConfigAck(1) state
= Req-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: COMPPROTO[6] 16 VJ slots
without slot compression
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: IPADDR[6] 64.7.134.129
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: State change Req-Sent
--> Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: RecvConfigReq(2) state
= Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: COMPPROTO[6] 16 VJ slots
without slot compression
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: IPADDR[6] 64.7.134.129
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: SendConfigAck(2) state
= Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: COMPPROTO[6] 16 VJ slots
without slot compression
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: IPADDR[6] 64.7.134.129
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: RecvConfigNak(1) state
= Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: IPADDR[6] 64.7.134.131
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: IPADDR[6] changing address:
0.0.0.0 --> 64.7.134.131
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: SendConfigReq(2) state
= Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: IPADDR[6] 64.7.134.131
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with
slot compression
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: PRIDNS[6] 199.212.134.11
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: SECDNS[6] 64.7.128.99
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: RecvConfigAck(2) state
= Ack-Sent
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: State change Ack-Sent
--> Opened
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: deflink: LayerUp.
Jun 19 18:57:30 iscar ppp[55]: tun0: IPCP: myaddr 64.7.134.131 hisaddr =
64.7.134.129
Jun 19 18:57:35 iscar ppp[55]: tun0: LCP: deflink: SendEchoRequest(1) state
= Opened
Jun 19 18:57:35 iscar ppp[55]: tun0: LCP: deflink: RecvEchoReply(1) state =
Opened
Jun 19 18:57:40 iscar ppp[55]: tun0: LCP: deflink: RecvEchoRequest(1) state
= Opened
Jun 19 18:57:40 iscar ppp[55]: tun0: LCP: deflink: SendEchoReply(1) state =
Opened
Jun 19 18:57:40 iscar ppp[55]: tun0: LCP: deflink: SendEchoRequest(2) state
= Opened
Jun 19 18:57:40 iscar ppp[55]: tun0: LCP: deflink: RecvEchoReply(2) state =
Opened
Jun 19 18:57:45 iscar ppp[55]: tun0: LCP: deflink: SendEchoRequest(3) state
= Opened
Jun 19 18:57:45 iscar ppp[55]: tun0: LCP: deflink: RecvEchoReply(3) state =
Opened
Jun 19 18:57:50 iscar ppp[55]: tun0: LCP: deflink: SendEchoRequest(4) state
= Opened
Jun 19 18:57:51 iscar ppp[55]: tun0: LCP: deflink: RecvEchoReply(4) state =
Opened
Jun 19 18:57:56 iscar ppp[55]: tun0: LCP: deflink: SendEchoRequest(5) state
= Opened
This was generated using
default:
#set log Phase Chat LCP IPCP CCP tun command
set log +lcp ipcp phase tun command ccp
ident user-ppp VERSION (built COMPILATIONDATE)
# Ensure that "device" references the correct serial port
# for your modem. (cuaa0 = COM1, cuaa1 = COM2)
#
set timeout 180 # 3 minute idle timer (the default)
enable dns # request DNS info (for resolv.conf)
papchap:
#
# edit the next three lines and replace the items in caps with
# the values which have been assigned by your ISP.
#
set phone PHONE_NUM
set authname USERNAME
set authkey PASSWORD
set ifaddr 10.0.0.1/0 10.0.0.2/0 255.255.255.0 0.0.0.0
add default HISADDR # Add a (sticky) default route
pppoe:
set device PPPoE:fxp1
#set mru 1454
#set mtu 1454
set speed sync
enable lqr
set lqrperiod 5
disable deflate pred1 mppe
deny deflate pred1 mppe
set cd 5
set dial
set login
set timeout 0
set authname username
set authkey thepassword
set ifaddr 10.0.0.1/0 10.0.0.2/0 255.255.255.0 0.0.0.0
add default HISADDR
and the virt template is
interface Virtual-Template1
mtu 1492
ip unnumbered Loopback0
peer default ip address pool dynamic1 dynamic2
ppp authentication pap chap callin optional
!
I have tried adjusting the virt template to 1452 and 1480 and 1454 without
luck.
---Mike
At 10:42 PM 6/19/2002 +0100, Brian Somers wrote:
>Can you send me a log of the connection with
>
> set log +lcp ipcp phase tun command ccp
>
>Cheers.
>
>On Wed, 19 Jun 2002 15:51:48 -0400, Mike Tancsa <mike@sentex.net> wrote:
> >
> > OK, just completed some more testing. Something is definitely really
> > strange between FreeBSD's PPPoE and the ERX. I have 2 FreeBSD boxes in 2
> > different locations, both that were working great off Redbacks. The Telco
> > switched out the Redbacks and put Unisphere ERXs in place. At these 2
> > sites, if I take out the FreeBSD boxes and put in either
> > Windows 2000,
> > Linux 2.4.x
> > or a Cisco 827
> > all works great. With FreeBSD, I can browse and fetch data from some
> > sites, but not all. The problem sites, transfer rates become bytes per
> second.
> > If I take out those 2 FreeBSD boxes and move them physically to a
> different
> > site where its terminated off a redback, all works as expected.
> >
> > So it would seem one or some of the following
> >
> > a) Something wrong with my config
> > b) Something wrong with the ERX
> > c) Something wrong with FreeBSD's PPPoE implementation as far as the
> ERX is
> > concerned.
> > d) Something wrong with my Telco's config.
> >
> >
> > a) is always possible. But the same simple PPPoE config has been working
> > for some time and the first box in question only stopped working when the
> > telco switch the termination device from a RedBack SMS to the ERX.
> > b) Possible, but all the other implementations seem to work
> > c) Not sure where to start
> > d) Again, certainly possible, but would it not affect all the PPPoE
> > implementations equally?
> >
> > Any help is much appreciated as I dont want to abandon FreeBSD of
> course at
> > these sites for Linux.
> >
> >
> > ---Mike
> >
>
>
>--
>Brian <brian@Awfulhak.org> <brian.somers@sun.com>
> <http://www.Awfulhak.org>; <brian@[uk.]FreeBSD.org>
>Don't _EVER_ lose your sense of humour ! <brian@[uk.]OpenBSD.org>
--------------------------------------------------------------------
Mike Tancsa, tel +1 519 651 3400
Sentex Communications, mike@sentex.net
Providing Internet since 1994 www.sentex.net
Cambridge, Ontario Canada www.sentex.net/mike
To Unsubscribe: send mail to majordomo@FreeBSD.org
with "unsubscribe freebsd-net" in the body of the message
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?5.1.0.14.0.20020619185445.031f0928>