Skip site navigation (1)Skip section navigation (2)
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>