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: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?529FA253.2000900>