ppp redial unsuccessful
Nick Gustas
tychl at mail.txf.com
Wed Oct 4 23:11:07 UTC 2006
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 at 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?
More information about the freebsd-stable
mailing list