Skip site navigation (1)Skip section navigation (2)
Date:      Wed, 04 Dec 2013 16:44:51 -0500
From:      Mike Tancsa <mike@sentex.net>
To:        freebsd-questions <freebsd-questions@freebsd.org>
Subject:   PPPoE help
Message-ID:  <529FA253.2000900@sentex.net>

Next in thread | Raw E-Mail | Index | Archive | Help
Googling around this problem occasionally comes up, but I have yet to
find a definitive answer.  An ISP is changing out their LACs and when
they are doing a hot cut, this sometimes messes up the pppoe ppp process
so it gets stuck in a loop and never recovers.  Killing off the ppp
process and restarts it works and all is fixed.

But this still on rare occasion will come up.  Does anyone know the
cause or work around ? I did manage to catch one and up the debug logs.

None debug looks like

Nov 26 15:30:01 s0332 ppp[1620]: tun1: IPCP: deflink: RecvConfigReq(10)
state = Initial
Nov 26 15:30:01 s0332 ppp[1620]: tun1: IPCP:  IPADDR[6] xx.yy.128.14
Nov 26 15:30:01 s0332 ppp[1620]: tun1: IPCP: deflink: Oops, RCR in Initial.
Nov 26 15:30:03 s0332 ppp[1620]: tun1: IPCP: deflink: RecvConfigReq(11)
state = Initial
Nov 26 15:30:03 s0332 ppp[1620]: tun1: IPCP:  IPADDR[6] xx.yy.128.14
Nov 26 15:30:03 s0332 ppp[1620]: tun1: IPCP: deflink: Oops, RCR in Initial.
Nov 26 15:30:04 s0332 ppp[1620]: tun1: LCP: deflink:
RecvEchoRequest(174) state = Opened
Nov 26 15:30:04 s0332 ppp[1620]: tun1: LCP: deflink: SendEchoReply(174)
state = Opened
Nov 26 15:30:05 s0332 ppp[1620]: tun1: IPCP: deflink: RecvConfigReq(12)
state = Initial


Config is simple


pppoe:
 add 10.6.153.2 HISADDR
 add default HISADDR
 set device PPPoE:vr0
 set server /var/run/spdsl-internet "" 0177
 set speed sync
 enable echo
 disable ipv6cp
 disable vjcomp
 set cd 15
 set dial
 set login
 set timeout 0
 set lqrperiod 10
 set authname s0332@realm
 set authkey xxxxxxxx
 set ifaddr 10.0.0.1/0 10.0.0.2/0 255.255.255.0 255.255.255.0

With debugging

Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: Select returns 1
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Physical: read
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Physical:  80 21 01 97 00 0a 03
06 43 2b 80 0e              .!......C+..
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Debug: deflink: DescriptorRead:
read 12/2048 from 1
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Sync: Read
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Sync:  80 21 01 97 00 0a 03 06 43
2b 80 0e              .!......C+..
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Debug: proto_LayerPull: unknown
-> 0x8021
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Debug: link_PullPacket: Despatch
proto 0x8021
Nov 26 16:53:20 s0332 ppp[1620]: tun1: IPCP: deflink: RecvConfigReq(151)
state = Initial
Nov 26 16:53:20 s0332 ppp[1620]: tun1: IPCP:  IPADDR[6] xx.yy.128.14
Nov 26 16:53:20 s0332 ppp[1620]: tun1: IPCP: deflink: Oops, RCR in Initial.
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: tun: fdset(r) 6
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: deflink(ctrl): fdset(r) 0
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: deflink: fdset(r) 1
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: deflink: fdset(e) 1
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: server: fdset(r) 9
Nov 26 16:53:20 s0332 ppp[1620]: tun1: Timer: prompt
/var/run/spdsl-internet: fdset(r) 2
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: Select returns -1
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: ---- Begin of Timer
Service List---
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: physical throughput
timer[0x28411068]: freq = 1.00s, next = 0.00s, state = running
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: lqm timer[0x28413df4]:
freq = 10.00s, next = 2.40s, state = running
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: hdlc timer[0x28413db0]:
freq = 60.00s, next = 52.40s, state = running
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: ---- End of Timer Service
List ---
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: timer_Start: Inserting
physical throughput timer[0x28411068] before lqm timer[0x28413df4],
delta = 10
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: tun: fdset(r) 6
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: deflink(ctrl): fdset(r) 0
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: deflink: fdset(r) 1
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: deflink: fdset(e) 1
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: server: fdset(r) 9
Nov 26 16:53:21 s0332 ppp[1620]: tun1: Timer: prompt
/var/run/spdsl-internet: fdset(r) 2
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: Select returns -1
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: ---- Begin of Timer
Service List---
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: physical throughput
timer[0x28411068]: freq = 1.00s, next = 0.00s, state = running
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: lqm timer[0x28413df4]:
freq = 10.00s, next = 1.40s, state = running
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: hdlc timer[0x28413db0]:
freq = 60.00s, next = 51.40s, state = running
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: ---- End of Timer Service
List ---
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: timer_Start: Inserting
physical throughput timer[0x28411068] before lqm timer[0x28413df4],
delta = 10
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: tun: fdset(r) 6
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: deflink(ctrl): fdset(r) 0
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: deflink: fdset(r) 1
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: deflink: fdset(e) 1
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: server: fdset(r) 9
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: prompt
/var/run/spdsl-internet: fdset(r) 2
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: Select returns 1
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Physical: read
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Physical:  80 21 01 98 00 0a 03
06 43 2b 80 0e              .!......C+..
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Debug: deflink: DescriptorRead:
read 12/2048 from 1
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Sync: Read
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Sync:  80 21 01 98 00 0a 03 06 43
2b 80 0e              .!......C+..
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Debug: proto_LayerPull: unknown
-> 0x8021
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Debug: link_PullPacket: Despatch
proto 0x8021
Nov 26 16:53:22 s0332 ppp[1620]: tun1: IPCP: deflink: RecvConfigReq(152)
state = Initial
Nov 26 16:53:22 s0332 ppp[1620]: tun1: IPCP:  IPADDR[6] xx.yy.128.14
Nov 26 16:53:22 s0332 ppp[1620]: tun1: IPCP: deflink: Oops, RCR in Initial.
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: tun: fdset(r) 6
Nov 26 16:53:22 s0332 ppp[1620]: tun1: Timer: deflink(ctrl): fdset(r) 0




-- 
-------------------
Mike Tancsa, tel +1 519 651 3400
Sentex Communications, mike@sentex.net
Providing Internet services since 1994 www.sentex.net
Cambridge, Ontario Canada   http://www.tancsa.com/



Want to link to this message? Use this URL: <http://docs.FreeBSD.org/cgi/mid.cgi?529FA253.2000900>