Date: Wed, 04 Oct 2006 19:10:54 -0400 From: Nick Gustas <tychl@mail.txf.com> To: cpghost <cpghost@cordula.ws>, Nick Gustas <tychl@mail.txf.com>, stable@freebsd.org, uspoerlein@gmail.com Subject: Re: ppp redial unsuccessful Message-ID: <45243F7E.8050708@mail.txf.com> In-Reply-To: <20061004213909.GC1848@roadrunner.q.local> 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>
next in thread | previous in thread | raw e-mail | index | archive | help
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?
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?45243F7E.8050708>