From owner-freebsd-stable@FreeBSD.ORG Wed Oct 4 23:11:07 2006 Return-Path: X-Original-To: stable@freebsd.org Delivered-To: freebsd-stable@FreeBSD.ORG Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 0D51916A403 for ; Wed, 4 Oct 2006 23:11:07 +0000 (UTC) (envelope-from tychl@mail.txf.com) Received: from rwcrmhc12.comcast.net (rwcrmhc12.comcast.net [216.148.227.152]) by mx1.FreeBSD.org (Postfix) with ESMTP id 4491143D4C for ; Wed, 4 Oct 2006 23:11:05 +0000 (GMT) (envelope-from tychl@mail.txf.com) Received: from masq.tychl.net (tychl.no-ip.org[67.174.137.176]) by comcast.net (rwcrmhc12) with ESMTP id <20061004231104m1200os710e>; Wed, 4 Oct 2006 23:11:04 +0000 Received: from localhost (localhost [127.0.0.1]) by masq.tychl.net (Postfix) with ESMTP id DE3731CB67; Wed, 4 Oct 2006 19:10:53 -0400 (EDT) X-Virus-Scanned: amavisd-new at tychl.net Received: from masq.tychl.net ([127.0.0.1]) by localhost (masq.tychl.net [127.0.0.1]) (amavisd-new, port 10024) with SMTP id oO84+MbJGI4i; Wed, 4 Oct 2006 19:10:50 -0400 (EDT) Received: from [127.0.0.1] (unknown [192.168.0.51]) by masq.tychl.net (Postfix) with ESMTP id EF0E81CB66; Wed, 4 Oct 2006 19:10:49 -0400 (EDT) Message-ID: <45243F7E.8050708@mail.txf.com> Date: Wed, 04 Oct 2006 19:10:54 -0400 From: Nick Gustas User-Agent: Thunderbird 1.5.0.7 (Windows/20060909) MIME-Version: 1.0 To: cpghost , Nick Gustas , stable@freebsd.org, uspoerlein@gmail.com References: <20061004185148.GA1848@roadrunner.q.local> <20061004185911.GA94703@epia2.farid-hajji.net> <20061004190611.GB1848@roadrunner.q.local> <45240D81.2080506@mail.txf.com> <20061004212417.GA95104@epia2.farid-hajji.net> <20061004213909.GC1848@roadrunner.q.local> In-Reply-To: <20061004213909.GC1848@roadrunner.q.local> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Cc: Subject: Re: ppp redial unsuccessful X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 04 Oct 2006 23:11:07 -0000 Ulrich Spoerlein wrote: > cpghost wrote: >> On Wed, Oct 04, 2006 at 03:37:37PM -0400, Nick Gustas wrote: >>> Not that it helps you much, but I do see working pppoe redial behavior >>> with Yahoo/AT&T dsl at a client site in the US. I can unhook the dsl >>> line and it will autoreconnect as soon as it's plugged in again. In the >>> event of a provider outage it comes back up on its own. The current ppp >>> session has been running for 59 days, longest session was 353 days, but >>> the server had to be moved for remodeling. >> Same here. I've got some 6.1-STABLE boxes running since 70 days >> uninterrupted on german T-Com ADSL (PPPoE). ppp redials automatically >> without any problems there. > > I maintain three FreeBSD boxes from 4.11 to 6.1-RELEASE and 6-STABLE. > They have been showing this for at least 1 or 2 years. So it is/was also > present in the 5.x line. > > I usually work around this by having a cron job that restarts ppp every > day at 04:00 or somewhere around that. > > So either I'm just unlucky or I'm doing something fundamentally wrong. > > Could someone paste me the snippet from ppp.log of a successful 24h > disconnect + redial? > > Thanks. > > Ulrich Spoerlein If all of those boxes are with the same provider I have to wonder if it's something on their end preventing the redial. I don't have physical access to the client box to pull the cable and I've only seen a drop in the event of an outage. Every time it has dropped, manually or otherwise, it gets a new IP address, and she generally has the same IP for months. My ppp.log only goes back 9 days because I've apparently been logging my LCP keepalives, so I don't have any reconnects in it. Sep 26 10:02:10 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvEchoRequest(19) state = Opened Sep 26 10:02:10 xxxxxxx ppp[55]: tun0: LCP: deflink: SendEchoReply(19) state = Opened ^^ 9 days of that. However, I forced a reconnect by doing a ifconfig dc0 down ; sleep 30 ; ifconfig dc0 up in a screen session here's the resulting ppp.log, note the "Connect time: 5195480 secs:" or 60.133 days. Oct 4 19:00:43 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvEchoRequest(122) state = Opened Oct 4 19:00:43 xxxxxxx ppp[55]: tun0: LCP: deflink: SendEchoReply(122) state = Opened Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: deflink: write (fd 1, len 86): Network is down Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: CCP: deflink: State change Stopped --> Closed Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: CCP: deflink: State change Closed --> Initial Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: LCP: deflink: LayerDown Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: LCP: deflink: State change Opened --> Starting Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: deflink: open -> lcp Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: IPCP: deflink: LayerDown: 64.149.135.98 Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: IPCP: deflink: State change Opened --> Starting Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: IPCP: deflink: LayerFinish. Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: IPCP: Connect time: 5195480 secs: 1934412196 octets in, 540652575 octets out Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: IPCP: 3723224 packets in, 2819374 packets out Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: IPCP: total 476 bytes/sec, peak 178816 bytes/sec on Tue Oct 3 15:25:50 2006 Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: IPCP: deflink: State change Starting --> Initial Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: bundle: Terminate Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: LCP: deflink: LayerFinish Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: LCP: deflink: State change Starting --> Initial Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: deflink: Disconnected! Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: deflink: lcp -> logout Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: deflink: Disconnected! Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: deflink: logout -> hangup Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: deflink: Connect time: 5195483 secs: 1927138891 octets in, 546464385 octets out Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: deflink: 3740513 packets in, 2836661 packets out Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: total 476 bytes/sec, peak 177877 bytes/sec on Tue Oct 3 15:25:49 2006 Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: deflink: hangup -> opening Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: bundle: Establish Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Phase: deflink: Enter pause (3) for redialing. Oct 4 19:02:30 xxxxxxx ppp[55]: tun0: Chat: deflink: Reconnect try 1 of 0 Oct 4 19:02:33 xxxxxxx ppp[55]: tun0: Chat: deflink: Redial timer expired. Oct 4 19:02:33 xxxxxxx ppp[55]: tun0: Phase: deflink: Connected! Oct 4 19:02:33 xxxxxxx ppp[55]: tun0: Phase: deflink: opening -> dial Oct 4 19:02:33 xxxxxxx ppp[55]: tun0: Phase: deflink: dial -> carrier Oct 4 19:02:35 xxxxxxx ppp[55]: tun0: Phase: Received NGM_PPPOE_ACNAME (hook "62031030047548-") Oct 4 19:02:38 xxxxxxx ppp[55]: tun0: Phase: deflink: Disconnected! Oct 4 19:02:38 xxxxxxx ppp[55]: tun0: Phase: deflink: carrier -> hangup Oct 4 19:02:38 xxxxxxx ppp[55]: tun0: Phase: deflink: Connect time: 5 secs: 0 octets in, 0 octets out Oct 4 19:02:38 xxxxxxx ppp[55]: tun0: Phase: deflink: 3740513 packets in, 2836661 packets out Oct 4 19:02:38 xxxxxxx ppp[55]: tun0: Phase: total 0 bytes/sec, peak 0 bytes/sec on Wed Oct 4 19:02:33 2006 Oct 4 19:02:38 xxxxxxx ppp[55]: tun0: Phase: deflink: hangup -> opening Oct 4 19:02:38 xxxxxxx ppp[55]: tun0: Phase: deflink: Enter pause (30) for redialing. Oct 4 19:03:08 xxxxxxx ppp[55]: tun0: Chat: deflink: Redial timer expired. Oct 4 19:03:08 xxxxxxx ppp[55]: tun0: Phase: deflink: Connected! Oct 4 19:03:08 xxxxxxx ppp[55]: tun0: Phase: deflink: opening -> dial Oct 4 19:03:08 xxxxxxx ppp[55]: tun0: Phase: deflink: dial -> carrier Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: Phase: Received NGM_PPPOE_ACNAME (hook "62031030047548-") Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: Phase: Received NGM_PPPOE_SESSIONID Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: Phase: Received NGM_PPPOE_SUCCESS Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: Phase: deflink: carrier -> login Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: Phase: deflink: login -> lcp Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: FSM: Using "deflink" as a transport Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: State change Initial --> Closed Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: State change Closed --> Stopped Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvConfigReq(125) state = Stopped Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MRU[4] 1492 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP) Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MAGICNUM[6] 0x43679182 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: Warning: deflink: Reducing configured MRU from 1500 to 1492 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: SendConfigReq(3) state = Stopped Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: ACFCOMP[2] Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: PROTOCOMP[2] Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: ACCMAP[6] 0x00000000 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MRU[4] 1492 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MAGICNUM[6] 0xd60bbe09 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: SendConfigAck(125) state = Stopped Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MRU[4] 1492 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP) Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MAGICNUM[6] 0x43679182 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: LayerStart Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: State change Stopped --> Ack-Sent Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvConfigRej(3) state = Ack-Sent Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: SendIdent(3) state = Ack-Sent Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MAGICNUM d60bbe09 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: TEXT user-ppp 3.2 (built Apr 25 2005) Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: ACFCOMP[2] Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: PROTOCOMP[2] Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: ACCMAP[6] 0x00000000 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: SendConfigReq(4) state = Ack-Sent Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MRU[4] 1492 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MAGICNUM[6] 0xd60bbe09 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvCodeRej(126) state = Ack-Sent Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvConfigAck(4) state = Ack-Sent Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MRU[4] 1492 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MAGICNUM[6] 0xd60bbe09 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: State change Ack-Sent --> Opened Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: LayerUp Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: SendIdent(4) state = Opened Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: MAGICNUM d60bbe09 Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: TEXT user-ppp 3.2 (built Apr 25 2005) Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: Phase: bundle: Authenticate Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: Phase: deflink: his = PAP, mine = none Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: Phase: Pap Output: xxxxxxx@ameritech.net ******** Oct 4 19:03:09 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvCodeRej(127) state = Opened Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: Phase: Pap Input: SUCCESS () Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: CCP: FSM: Using "deflink" as a transport Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: CCP: deflink: State change Initial --> Closed Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: CCP: deflink: LayerStart. Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: CCP: MPPE: Not usable without CHAP81 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: CCP: deflink: SendConfigReq(1) state = Closed Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: CCP: DEFLATE[4] win 15 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: CCP: PRED1[2] Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: CCP: deflink: State change Closed --> Req-Sent Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: Phase: deflink: lcp -> open Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: Phase: bundle: Network Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: FSM: Using "deflink" as a transport Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: State change Initial --> Closed Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: LayerStart. Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: SendConfigReq(4) state = Closed Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: IPADDR[6] 64.149.135.98 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: PRIDNS[6] 66.73.20.40 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: SECDNS[6] 206.141.193.55 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: State change Closed --> Req-Sent Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: RecvConfigReq(145) state = Req-Sent Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: IPADDR[6] 69.209.127.254 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: SendConfigAck(145) state = Req-Sent Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: IPADDR[6] 69.209.127.254 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: State change Req-Sent --> Ack-Sent Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvProtocolRej(97) state = Opened Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: LCP: deflink: -- Protocol 0x80fd (Compression Control Protocol) was rejected! Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: CCP: deflink: State change Req-Sent --> Stopped Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: RecvConfigRej(4) state = Ack-Sent Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: LCP: deflink: SendIdent(5) state = Opened Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: LCP: MAGICNUM d60bbe09 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: LCP: TEXT user-ppp 3.2 (built Apr 25 2005) Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: SendConfigReq(5) state = Ack-Sent Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: IPADDR[6] 64.149.135.98 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: PRIDNS[6] 66.73.20.40 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: SECDNS[6] 206.141.193.55 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvProtocolRej(98) state = Opened Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: LCP: deflink: -- Protocol 0x8057 (Internet Protocol V6 Control Protocol) was rejected! Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: Phase: deflink: IPV6CP protocol reject closes IPV6CP ! Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvCodeRej(99) state = Opened Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: RecvConfigNak(5) state = Ack-Sent Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: IPADDR[6] 69.209.118.127 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: IPADDR[6] changing address: 64.149.135.98 --> 69.209.118.127 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: SendConfigReq(6) state = Ack-Sent Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: IPADDR[6] 69.209.118.127 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: PRIDNS[6] 66.73.20.40 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: SECDNS[6] 206.141.193.55 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: LCP: deflink: RecvProtocolRej(100) state = Opened Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: LCP: deflink: -- Protocol 0x8057 (Internet Protocol V6 Control Protocol) was rejected! Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: Phase: deflink: IPV6CP protocol reject closes IPV6CP ! Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: RecvConfigAck(6) state = Ack-Sent Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: IPADDR[6] 69.209.118.127 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: PRIDNS[6] 66.73.20.40 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: SECDNS[6] 206.141.193.55 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: State change Ack-Sent --> Opened Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: deflink: LayerUp. Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: IPCP: myaddr 69.209.118.127 hisaddr = 69.209.127.254 Oct 4 19:03:11 xxxxxxx ppp[55]: tun0: Command: papchap: iface clear The real question is, is there's a way to work around your provider's brokenness without killing the ppp process?