From owner-freebsd-questions@FreeBSD.ORG Wed Dec 4 21:44:35 2013 Return-Path: Delivered-To: freebsd-questions@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id 826C6F44 for ; Wed, 4 Dec 2013 21:44:35 +0000 (UTC) Received: from smarthost1.sentex.ca (smarthost1-6.sentex.ca [IPv6:2607:f3e0:0:1::12]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.freebsd.org (Postfix) with ESMTPS id 222AB138D for ; Wed, 4 Dec 2013 21:44:35 +0000 (UTC) Received: from [192.168.43.26] (pyroxene.sentex.ca [199.212.134.18]) by smarthost1.sentex.ca (8.14.7/8.14.7) with ESMTP id rB4LiX2c008108 for ; Wed, 4 Dec 2013 16:44:33 -0500 (EST) (envelope-from mike@sentex.net) Message-ID: <529FA253.2000900@sentex.net> Date: Wed, 04 Dec 2013 16:44:51 -0500 From: Mike Tancsa Organization: Sentex Communications User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20100101 Thunderbird/24.1.1 MIME-Version: 1.0 To: freebsd-questions Subject: PPPoE help X-Enigmail-Version: 1.6 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit X-Scanned-By: MIMEDefang 2.74 on 64.7.153.18 X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.17 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 04 Dec 2013 21:44:35 -0000 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/