> On Thu, 30 Nov 2000 11:40:49 -0600, in a place far, far away,
> monitor glow in such a way as to indicate that:
>>Different hardware might mean a different configuration is needed
>>for the one that doesn't work. Add the pppd option "debug" and the
>>chat -v options and post exact copies, including timestamps, of the
>>log messages, usually found in a file or files in /var/log.
> OK, here's the log (ignore the date--I really did do it today--the
> clock's just screwed up on my machine, and I've had other problems...
> <g>)
> Nov 25 15:00:38 localhost pppd[1797]: pppd 2.3.11 started by root, uid
> 0
There was nothing in the first part of the log to suggest the source
of the trouble.
Quote:> Nov 25 15:01:02 localhost chat[1798]: expect (PP session)
> Nov 25 15:01:02 localhost chat[1798]: ^M
> Nov 25 15:01:02 localhost chat[1798]: Packet mode enabled: PPP session
> Nov 25 15:01:02 localhost chat[1798]: -- got it
> Nov 25 15:01:02 localhost chat[1798]: send (/d/c^M)
You're not in Kansas anymore. The send part of the expect-send beginning
with ``PP session'' should be ``\d\c'' not ``/d/c''. :) There is
a small chance that this is the origin of the problem, but it's really
very small.
Quote:> Nov 25 15:01:02 localhost pppd[1797]: Serial connection established.
> Nov 25 15:01:02 localhost pppd[1797]: Using interface ppp0
> Nov 25 15:01:02 localhost pppd[1797]: Connect: ppp0 <--> /dev/ttyS1
> Nov 25 15:01:03 localhost pppd[1797]: sent [LCP ConfReq id=0x1
> <asyncmap 0x0> <magic 0x967252d2> <pcomp> <accomp>]
> Nov 25 15:01:03 localhost pppd[1797]: rcvd [LCP ConfAck id=0x1
> <asyncmap 0x0> <magic 0x967252d2> <pcomp> <accomp>]
> Nov 25 15:01:05 localhost pppd[1797]: rcvd [LCP ConfReq id=0x2 <mru
> 1500> <asyncmap 0x0> <magic 0xff71a12c> <pcomp> <accomp>]
> Nov 25 15:01:05 localhost pppd[1797]: sent [LCP ConfAck id=0x2 <mru
> 1500> <asyncmap 0x0> <magic 0xff71a12c> <pcomp> <accomp>]
These all look normal.
Quote:> Nov 25 15:01:05 localhost pppd[1797]: sent [IPCP ConfReq id=0x1 <addr
> 0.0.0.0> <compress VJ 0f 01>]
> Nov 25 15:01:05 localhost pppd[1797]: rcvd [IPCP ConfReq id=0x1
> <compress VJ 0f 00> <addr 163.179.37.84>]
> Nov 25 15:01:05 localhost pppd[1797]: sent [IPCP ConfAck id=0x1
> <compress VJ 0f 00> <addr 163.179.37.84>]
Often the different VJ compression codes (0f 01 versus 0f 00) is a
sign of trouble to come.
Quote:> Nov 25 15:01:05 localhost pppd[1797]: rcvd [IPCP ConfNak id=0x1 <addr
> 205.184.165.241>]
> Nov 25 15:01:05 localhost pppd[1797]: sent [IPCP ConfReq id=0x2 <addr
> 205.184.165.241> <compress VJ 0f 01>]
> Nov 25 15:01:06 localhost pppd[1797]: rcvd [IPCP ConfAck id=0x2 <addr
> 205.184.165.241> <compress VJ 0f 01>]
> Nov 25 15:01:06 localhost pppd[1797]: local IP address 205.184.165.241
> Nov 25 15:01:06 localhost pppd[1797]: remote IP address 163.179.37.84
> Nov 25 15:01:06 localhost pppd[1797]: Script /etc/ppp/ip-up started
> (pid 1801)
All looks to be okay to this point. Both sides have an IP address.
Quote:> Nov 25 15:01:06 localhost pppd[1797]: rcvd [CCP ConfReq id=0x1 < 11 05
> 00 01 04>]
> Nov 25 15:01:06 localhost pppd[1797]: sent [CCP ConfReq id=0x1]
> Nov 25 15:01:06 localhost pppd[1797]: sent [CCP ConfRej id=0x1 < 11 05
> 00 01 04>]
> Nov 25 15:01:06 localhost pppd[1797]: rcvd [CCP ConfReq id=0x2 < 11 05
> 00 01 03>]
> Nov 25 15:01:06 localhost pppd[1797]: sent [CCP ConfRej id=0x2 < 11 05
> 00 01 03>]
> Nov 25 15:01:06 localhost pppd[1797]: rcvd [CCP ConfReq id=0x3 < 11 05
> 00 00 00>]
> Nov 25 15:01:06 localhost pppd[1797]: sent [CCP ConfRej id=0x3 < 11 05
> 00 00 00>]
The peer tries to get pppd to accept several varieties STAC LZS CCP.
Pppd rejects them all since STAC LZS requires a license and cannot be
GPLed for an open source distribution.
Quote:> Nov 25 15:01:06 localhost pppd[1797]: rcvd [CCP ConfReq id=0x4 < 12 06
> 00 00 00 01>]
> Nov 25 15:01:06 localhost pppd[1797]: sent [CCP ConfRej id=0x4 < 12 06
> 00 00 00 01>]
> Nov 25 15:01:06 localhost pppd[1797]: Script /etc/ppp/ip-up finished
> (pid 1801), status = 0x0
Then the peer requests a variety of MS-PCC CCP, which pppd cannot
support either, and pppd rejects these too. This can be fatal but
it shouldn't be here, it's just not the right type for that to
happen.
Quote:> Nov 25 15:01:09 localhost pppd[1797]: sent [CCP ConfReq id=0x1]
> Nov 25 15:01:09 localhost pppd[1797]: rcvd [CCP TermReq id=0x6]
> Nov 25 15:01:09 localhost pppd[1797]: sent [CCP TermAck id=0x6]
This sequence keeps repeating until the INT signal to pppd.
Here things seem to really go wrong, pppd tries to complete
the CCP negotiations that the peer started by sending an "empty"
Configure-Request, and the peer sends a CCP Terminate-Request, which
is not permitted by the PPP state machine until the CCP protocol
negotiation reachs the open state.
The peer has only two choices, to accept the pppd request for CCP
with no options to complete the CCP negotiations, or to send a
Protocol-Reject. The peer is broken with respect to CCP negotiations.
You can try adding the pppd noccp option which will cause pppd to
Protocol-Reject the peer's attempt to negotiate CCP at the very start
of CCP negotiation. You won't lose anything since pppd and the peer
have no common CCP algorithm anyway.
You can also try adding novj to keep VJ compression from being
negotiated.
The interesting question is why the connection is successful under the
2.2.15 kernel, but not under the 2.2.16 one with the same scripts and
options, and presumably the same version of pppd - 2.3.11 here. I'd be
very interested in seeing the traces for the successful connection under
the 2.2.15 kernel, and to know whether the same pppd version is used
or not.
--
/* Editing with vi is a lot better than using a huge swiss army knife.
Use =} to wrap paragraphs in vi. Or put map ^] !}fmt -72^M in
~/.exrc and use ^] to wrap to 72 columns or whatever you choose. */
by