Date: Thu, 21 Sep 2000 13:16:08 +0400 From: "Michael Kuzmin" <kuzmin@laser.ru> To: "Brian Somers" <brian@Awfulhak.org> Cc: <freebsd-net@freebsd.org> Subject: Re: Dying multi-link PPP Message-ID: <009801c023ae$078c70e0$1e0657c2@w9g8j7> References: <200009202156.e8KLuws19704@hak.lan.Awfulhak.org>
next in thread | previous in thread | raw e-mail | index | archive | help
>> Our configuration is fairly standard, user-ppp with two modems and MP
>> enabled at both sides of the channel (see ppp.conf below), the only
>> pecularity is frequent redials due to telco (30 min call limit). It always
>> works OK after reload and initial connects, but subsequent modem redials
>> amont to accumulation of problems and performance degradation with
>> unavoidable death in several hours.
>>
>> The usual final (dead) state of the channel is an infinite series of short
>> connects each with LCP RecvTerminateReq in 15 sec after successful
>> authorization and lcp -> open. The origin of this dead state could be
>> tentitavely traced to simultaneous redial of both modem links, at that
>> moment old ppp master at answering side exits and all new ppp processes
>> born after that seems to unable to continue...
> [.....]
>
> I think the first thing to find out is why the SendTerminateReq is
> being sent. If you enable debug, lcp, ipcp & tcp/ip logs on that end
> (the server?), hopefully we'll see why it thinks it's a good idea to
> give up.
>
> You could also try
>
> disable pred1 deflate
> deny pred1 deflate
>
> in your mpd profile - I believe there may be a problem with compression
> at the moment.
Thank you for this idea - I'll try it a bit later.
Meanwhile, it should be noted that we really _have_ many CCP-related errors
in logs, e.g. sequenses like that
15:56:30 atd ppp[336]: tun0: CCP: mp: RecvResetReq(11) state = Opened
15:56:30 atd ppp[336]: tun0: CCP: Deflate: Output channel reset
15:56:30 atd ppp[336]: tun0: CCP: mp: SendResetAck(11) state = Opened
repeated tens or hundreds time in a line (or even for half an hour - our max
lifetime of the link)
And I can also post some logs that I already have archived - these logs seems
to be relevant.
Here is what is going on around when SendTerminateReq is being sent
(all logging you requested exept debug were on, configs are just
that I posted last time):
19:52:00 atd ppp[915]: tun0: Phase: deflink: his = PAP, mine = PAP
19:52:00 atd ppp[915]: tun0: Phase: Pap Output: atd ********
19:52:00 atd ppp[915]: tun0: Phase: Pap Input: REQUEST (ata)
19:52:00 atd ppp[915]: tun0: ID0: 0x28168fa4 =fopen("/etc/ppp/ppp.secret", "r")
19:52:00 atd ppp[915]: tun0: Phase: Pap Output: SUCCESS
19:52:00 atd ppp[915]: tun0: ID0: login("cuaa1", "ata")
19:52:00 atd ppp[915]: tun0: Phase: Pap Input: SUCCESS (Greetings!!)
19:52:00 atd ppp[915]: tun0: ID0: 1 = socket(1, 2, 0)
19:52:00 atd ppp[915]: tun0: ID0: 0 = bind(1, "/var/run/ppp-ata-00-",106)
19:52:00 atd ppp[915]: tun0: Phase: mp: Listening on /var/run/ppp-ata-00-
19:52:00 atd ppp[915]: tun0: Phase: First link: deflink
19:52:00 atd ppp[915]: tun0: CCP: FSM: Using "mp" as a transport
19:52:00 atd ppp[915]: tun0: CCP: mp: State change Initial --> Closed
19:52:00 atd ppp[915]: tun0: CCP: mp: LayerStart.
19:52:00 atd ppp[915]: tun0: CCP: mp: SendConfigReq(1) state = Closed
19:52:00 atd ppp[915]: tun0: CCP: DEFLATE[4] win 15
19:52:00 atd ppp[915]: tun0: CCP: PRED1[2]
19:52:00 atd ppp[915]: tun0: CCP: mp: State change Closed -->Req-Sent
19:52:00 atd ppp[915]: tun0: ID0: 0x28168fa4 = fopen("/etc/ppp/ppp.secret", "r")
19:52:00 atd ppp[915]: tun0: CCP: FSM: Using "deflink" as a transport
19:52:00 atd ppp[915]: tun0: CCP: deflink: State change Initial -->Closed
19:52:00 atd ppp[915]: tun0: CCP: deflink: State change Closed -->Stopped
19:52:00 atd ppp[915]: tun0: Phase: deflink: lcp -> open
19:52:00 atd ppp[915]: tun0: Phase: bundle: Network
19:52:00 atd ppp[915]: tun0: IPCP: FSM: Using "mp" as a transport
19:52:00 atd ppp[915]: tun0: IPCP: mp: State change Initial -->Closed
19:52:00 atd ppp[915]: tun0: IPCP: mp: LayerStart.
19:52:00 atd ppp[915]: tun0: IPCP: mp: SendConfigReq(1) state =Closed
19:52:00 atd ppp[915]: tun0: IPCP: IPADDR[6] 195.209.192.1
19:52:00 atd ppp[915]: tun0: IPCP: mp: State change Closed -->Req-Sent
19:52:00 atd ppp[915]: tun0: Phase: Unknown protocol 0x00fd (1st choice compression)
19:52:00 atd ppp[915]: tun0: LCP: mp: SendProtocolRej(1) state =Opened
19:52:00 atd ppp[915]: tun0: Warning: ip_Input: IPCP not open - packet dropped
19:52:00 atd ppp[915]: tun0: Phase: Unknown protocol 0x00fd (1st choice compression)
19:52:00 atd ppp[915]: tun0: LCP: mp: SendProtocolRej(1) state = Opened
19:52:03 atd ppp[915]: tun0: CCP: mp: SendConfigReq(1) state = Req-Sent
19:52:03 atd ppp[915]: tun0: CCP: DEFLATE[4] win 15
19:52:03 atd ppp[915]: tun0: CCP: PRED1[2]
19:52:03 atd ppp[915]: tun0: IPCP: mp: SendConfigReq(1) state =Req-Sent
19:52:03 atd ppp[915]: tun0: IPCP: IPADDR[6] 195.209.192.1
19:52:06 atd ppp[915]: tun0: CCP: mp: SendConfigReq(1) state =Req-Sent
19:52:06 atd ppp[915]: tun0: CCP: DEFLATE[4] win 15
19:52:06 atd ppp[915]: tun0: CCP: PRED1[2]
19:52:06 atd ppp[915]: tun0: IPCP: mp: SendConfigReq(1) state =Req-Sent
19:52:06 atd ppp[915]: tun0: IPCP: IPADDR[6] 195.209.192.1
19:52:09 atd ppp[915]: tun0: CCP: mp: SendConfigReq(1) state =Req-Sent
19:52:09 atd ppp[915]: tun0: CCP: DEFLATE[4] win 15
19:52:09 atd ppp[915]: tun0: CCP: PRED1[2]
19:52:09 atd ppp[915]: tun0: IPCP: mp: SendConfigReq(1) state =Req-Sent
19:52:09 atd ppp[915]: tun0: IPCP: IPADDR[6] 195.209.192.1
19:52:12 atd ppp[915]: tun0: CCP: mp: SendConfigReq(1) state =Req-Sent
19:52:12 atd ppp[915]: tun0: CCP: DEFLATE[4] win 15
19:52:12 atd ppp[915]: tun0: CCP: PRED1[2]
19:52:12 atd ppp[915]: tun0: IPCP: mp: SendConfigReq(1) state =Req-Sent
19:52:12 atd ppp[915]: tun0: IPCP: IPADDR[6] 195.209.192.1
19:52:15 atd ppp[915]: tun0: CCP: mp: LayerFinish.
19:52:15 atd ppp[915]: tun0: CCP: mp: State change Req-Sent -->Stopped
19:52:15 atd ppp[915]: tun0: IPCP: mp: LayerFinish.
19:52:15 atd ppp[915]: tun0: IPCP: Connect time: 15 secs: 0 octets in, 0 octets out
19:52:15 atd ppp[915]: tun0: IPCP: total 0 bytes/sec, peak 0 bytes/sec on Thu 19:52:15 2000
19:52:15 atd ppp[915]: tun0: IPCP: mp: State change Req-Sent -->Stopped
19:52:15 atd ppp[915]: tun0: Phase: bundle: Terminate
19:52:15 atd ppp[915]: tun0: ID0: 0 = unlink("/var/run/ppp-ata-00-")
19:52:15 atd ppp[915]: tun0: CCP: mp: State change Stopped --> Closed
19:52:15 atd ppp[915]: tun0: CCP: mp: State change Closed --> Initial
19:52:15 atd ppp[915]: tun0: CCP: deflink: State change Stopped -->Closed
19:52:15 atd ppp[915]: tun0: CCP: deflink: State change Closed -->Initial
19:52:15 atd ppp[915]: tun0: LCP: deflink: LayerDown
19:52:15 atd ppp[915]: tun0: LCP: deflink: SendTerminateReq(2) state= Opened
19:52:15 atd ppp[915]: tun0: LCP: deflink: State change Opened -->Closing
19:52:15 atd ppp[915]: tun0: Phase: deflink: open -> lcp
19:52:15 atd ppp[915]: tun0: IPCP: mp: State change Stopped -->Closed
19:52:15 atd ppp[915]: tun0: IPCP: mp: State change Closed -->Initial
19:52:16 atd ppp[915]: tun0: LCP: deflink: RecvTerminateAck(2) state = Closing
19:52:16 atd ppp[915]: tun0: LCP: deflink: LayerFinish
19:52:16 atd ppp[915]: tun0: LCP: deflink: State change Closing --> Closed
19:52:16 atd ppp[915]: tun0: LCP: deflink: State change Closed -->Initial
19:52:16 atd ppp[915]: tun0: Phase: deflink: Disconnected!
19:52:16 atd ppp[915]: tun0: ID0: logout("cuaa1")
19:52:16 atd ppp[915]: tun0: ID0: logwtmp("cuaa1", "", "")
19:52:16 atd ppp[915]: tun0: Phase: deflink: Connect time: 17 secs: 472 octets in, 619 octets out
19:52:16 atd ppp[915]: tun0: Phase: total 64 bytes/sec, peak 301 bytes/sec on Thu 19:52:16 2000
19:52:16 atd ppp[920]: tun0: ID0: 0x28168fa4 = fopen("/var/run/tun0.pid", "w")
19:52:16 atd ppp[920]: tun0: ID0: 0 = unlink("/var/run/cuaa1.if")
19:52:16 atd ppp[920]: tun0: Phase: deflink: lcp -> closed
19:52:16 atd ppp[920]: tun0: ID0: 0 = socket(2, 2, 0)
19:52:16 atd ppp[920]: tun0: ID0: 0 = ioctl(0, 3223349521, 0xbfbfd044)
19:52:16 atd ppp[920]: tun0: ID0: 0 = ioctl(0, 2149607696, 0xbfbfd044)
19:52:16 atd ppp[920]: tun0: Phase: bundle: Dead
19:52:16 atd ppp[920]: tun0: Phase: PPP Terminated (normal).
19:52:16 atd ppp[920]: tun0: ID0: 0 = socket(2, 2, 0)
19:52:16 atd ppp[920]: tun0: ID0: 0 = ioctl(0, 3223349521, 0xbfbfdbac)
19:52:16 atd ppp[920]: tun0: ID0: 0 = ioctl(0, 2149607696, 0xbfbfdbac)
19:52:16 atd ppp[920]: tun0: ID0: 0 = unlink("/var/run/tun0.pid")
This is repeated for each incoming call...
When looking at that myself, I suspected that they faled to negotiate a
compression protocol and then tried to switch off one of them (deflate) to
make the negotiation easier :-) That did not help.
If it actually compression, what may happen here?...
It _did_ work an hour earlier, the same run, same configs...
Sincerely yours,
Michael Kuzmun,
LASERnet
To Unsubscribe: send mail to majordomo@FreeBSD.org
with "unsubscribe freebsd-net" in the body of the message
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?009801c023ae$078c70e0$1e0657c2>