strange pppd error

strange pppd error

[walter harms]

Hi List,
i run pppd 2.4.2 in an embedded environment since years. Now i have seen a
problem that i never encountered before.

Two modem got stuck while handshake. below you can see the logs i have  (actualy
that is a factual endless loop, what means you see only a few bytes from several megs.)

i would like to prevent this from happening again. any with an idea out there ?

(it does not seem to be reproducible. after reset the device behaves normal.)
re
 wh

Oct 20 13:56:09  pppd[5792]: sent [LCP EchoReq id=0x0 magic=0xd71a0c90]
Oct 20 13:56:09  pppd[5792]: sent [IPCP ConfReq id=0xc8 <compress VJ 0f 01> <addr 10.0.0.2>]
Oct 20 13:56:09  pppd[5792]: rcvd [CCP ConfReq id=0xc7 <deflate 15> <deflate(old#) 15>]
Oct 20 13:56:09  pppd[5792]: sent [CCP ConfReq id=0xbb]
Oct 20 13:56:09  pppd[5792]: sent [CCP ConfRej id=0xc7 <deflate 15> <deflate(old#) 15>]
Oct 20 13:56:09  pppd[5792]: rcvd [IPCP ConfReq id=0xc7 <compress VJ 0f 01> <addr 0.0.0.0>]
Oct 20 13:56:09  pppd[5792]: sent [IPCP ConfNak id=0xc7 <addr 10.0.0.1>]
Oct 20 13:56:12  pppd[5792]: rcvd [LCP ConfReq id=0xc8 <asyncmap 0x0> <magic 0xab132318> <pcomp> <accomp>]
Oct 20 13:56:12  pppd[5792]: sent [LCP ConfReq id=0xc9 <asyncmap 0x0> <magic 0xf79dba92> <pcomp> <accomp>]
Oct 20 13:56:12  pppd[5792]: sent [LCP ConfAck id=0xc8 <asyncmap 0x0> <magic 0xab132318> <pcomp> <accomp>]
Oct 20 13:56:12  pppd[5792]: rcvd [LCP ConfAck id=0xc8 <asyncmap 0x0> <magic 0xd71a0c90> <pcomp> <accomp>]
Oct 20 13:56:12  pppd[5792]: rcvd [LCP EchoReq id=0x0 magic=0xab132318]
Oct 20 13:56:12  pppd[5792]: rcvd [LCP EchoRep id=0x0 magic=0xab132318]
Oct 20 13:56:12  pppd[5792]: rcvd [CCP ConfReq id=0xc8 <deflate 15> <deflate(old#) 15>]
Oct 20 13:56:12  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 13:56:12  pppd[5792]: rcvd [IPCP ConfReq id=0xc8 <compress VJ 0f 01> <addr 0.0.0.0>]
Oct 20 13:56:12  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 13:56:12  pppd[5792]: rcvd [IPCP ConfAck id=0xc8 <compress VJ 0f 01> <addr 10.0.0.2>]
Oct 20 13:56:12  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 13:56:12  pppd[5792]: rcvd [CCP ConfAck id=0xbb]
Oct 20 13:56:12  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 13:56:14  pppd[5792]: sent [LCP ConfReq id=0xc9 <asyncmap 0x0> <magic 0xf79dba92> <pcomp> <accomp>]
Oct 20 13:56:15  pppd[5792]: rcvd [LCP ConfReq id=0xc9 <asyncmap 0x0> <magic 0xb84a827a> <pcomp> <accomp>]
Oct 20 13:56:15  pppd[5792]: sent [LCP ConfAck id=0xc9 <asyncmap 0x0> <magic 0xb84a827a> <pcomp> <accomp>]
Oct 20 13:56:15  pppd[5792]: rcvd [LCP ConfAck id=0xc9 <asyncmap 0x0> <magic 0xf79dba92> <pcomp> <accomp>]
Oct 20 13:56:15  pppd[5792]: sent [LCP EchoReq id=0x0 magic=0xf79dba92]
Oct 20 13:56:15  pppd[5792]: sent [IPCP ConfReq id=0xc9 <compress VJ 0f 01> <addr 10.0.0.2>]
Oct 20 13:56:15  pppd[5792]: rcvd [CCP ConfReq id=0xc8 <deflate 15> <deflate(old#) 15>]
Oct 20 13:56:15  pppd[5792]: sent [CCP ConfReq id=0xbc]
Oct 20 13:56:15  pppd[5792]: sent [CCP ConfRej id=0xc8 <deflate 15> <deflate(old#) 15>]
Oct 20 13:56:15  pppd[5792]: rcvd [IPCP ConfReq id=0xc8 <compress VJ 0f 01> <addr 0.0.0.0>]
Oct 20 13:56:15  pppd[5792]: sent [IPCP ConfNak id=0xc8 <addr 10.0.0.1>]
Oct 20 13:56:18  pppd[5792]: sent [IPCP ConfReq id=0xc9 <compress VJ 0f 01> <addr 10.0.0.2>]
Oct 20 13:56:18  pppd[5792]: sent [CCP ConfReq id=0xbc]
Oct 20 13:56:18  pppd[5792]: rcvd [LCP ConfReq id=0xc9 <asyncmap 0x0> <magic 0xb84a827a> <pcomp> <accomp>]
Oct 20 13:56:18  pppd[5792]: sent [LCP ConfReq id=0xca <asyncmap 0x0> <magic 0x577826a2> <pcomp> <accomp>]
Oct 20 13:56:18  pppd[5792]: sent [LCP ConfAck id=0xc9 <asyncmap 0x0> <magic 0xb84a827a> <pcomp> <accomp>]
Oct 20 13:56:18  pppd[5792]: rcvd [LCP ConfAck id=0xc9 <asyncmap 0x0> <magic 0xf79dba92> <pcomp> <accomp>]
Oct 20 13:56:18  pppd[5792]: rcvd [LCP EchoReq id=0x0 magic=0xb84a827a]
Oct 20 13:56:18  pppd[5792]: rcvd [LCP EchoRep id=0x0 magic=0xb84a827a]
Oct 20 13:56:18  pppd[5792]: rcvd [CCP ConfReq id=0xc9 <deflate 15> <deflate(old#) 15>]
Oct 20 13:56:18  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 13:56:18  pppd[5792]: rcvd [IPCP ConfReq id=0xc9 <compress VJ 0f 01> <addr 0.0.0.0>]
Oct 20 13:56:18  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 13:56:18  pppd[5792]: rcvd [IPCP ConfAck id=0xc9 <compress VJ 0f 01> <addr 10.0.0.2>]
Oct 20 13:56:18  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 13:56:18  pppd[5792]: rcvd [CCP ConfAck id=0xbc]
Oct 20 13:56:18  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 13:56:20  pppd[5792]: sent [LCP ConfReq id=0xca <asyncmap 0x0> <magic 0x577826a2> <pcomp> <accomp>]
Oct 20 13:56:21  pppd[5792]: rcvd [LCP ConfReq id=0xca <asyncmap 0x0> <magic 0x1683b46a> <pcomp> <accomp>]
Oct 20 13:56:21  pppd[5792]: sent [LCP ConfAck id=0xca <asyncmap 0x0> <magic 0x1683b46a> <pcomp> <accomp>]
Oct 20 13:56:21  pppd[5792]: rcvd [LCP ConfAck id=0xca <asyncmap 0x0> <magic 0x577826a2> <pcomp> <accomp>]
Oct 20 13:56:21  pppd[5792]: sent [LCP EchoReq id=0x0 magic=0x577826a2]
Oct 20 13:56:21  pppd[5792]: sent [IPCP ConfReq id=0xca <compress VJ 0f 01> <addr 10.0.0.2>]
Oct 20 13:56:21  pppd[5792]: rcvd [CCP ConfReq id=0xc9 <deflate 15> <deflate(old#) 15>]
Oct 20 13:56:21  pppd[5792]: sent [CCP ConfReq id=0xbd]
Oct 20 13:56:21  pppd[5792]: sent [CCP ConfRej id=0xc9 <deflate 15> <deflate(old#) 15>]
Oct 20 13:56:21  pppd[5792]: rcvd [IPCP ConfReq id=0xc9 <compress VJ 0f 01> <addr 0.0.0.0>]
Oct 20 13:56:21  pppd[5792]: sent [IPCP ConfNak id=0xc9 <addr 10.0.0.1>]
Oct 20 13:56:24  pppd[5792]: rcvd [LCP ConfReq id=0xca <asyncmap 0x0> <magic 0x1683b46a> <pcomp> <accomp>]
Oct 20 13:56:24  pppd[5792]: sent [LCP ConfReq id=0xcb <asyncmap 0x0> <magic 0x75410637> <pcomp> <accomp>

Re: strange pppd error

[James Carlson]

walter harms wrote:
> Oct 20 13:56:09  pppd[5792]: sent [LCP EchoReq id=0x0 magic=0xd71a0c90]
> Oct 20 13:56:09  pppd[5792]: sent [IPCP ConfReq id=0xc8 <compress VJ 0f 01> <addr 10.0.0.2>]
> Oct 20 13:56:09  pppd[5792]: rcvd [CCP ConfReq id=0xc7 <deflate 15> <deflate(old#) 15>]
> Oct 20 13:56:09  pppd[5792]: sent [CCP ConfReq id=0xbb]
> Oct 20 13:56:09  pppd[5792]: sent [CCP ConfRej id=0xc7 <deflate 15> <deflate(old#) 15>]
> Oct 20 13:56:09  pppd[5792]: rcvd [IPCP ConfReq id=0xc7 <compress VJ 0f 01> <addr 0.0.0.0>]
> Oct 20 13:56:09  pppd[5792]: sent [IPCP ConfNak id=0xc7 <addr 10.0.0.1>]

It looks like LCP was in Opened state up to this point.

> Oct 20 13:56:12  pppd[5792]: rcvd [LCP ConfReq id=0xc8 <asyncmap 0x0> <magic 0xab132318> <pcomp> <accomp>]

Something (perhaps a system reset) caused the peer to restart LCP.  This
is event RCR+ for us (see RFC 1661), which causes us to do tld,src,sca
and go to state Ack-Sent.

> Oct 20 13:56:12  pppd[5792]: sent [LCP ConfReq id=0xc9 <asyncmap 0x0> <magic 0xf79dba92> <pcomp> <accomp>]
> Oct 20 13:56:12  pppd[5792]: sent [LCP ConfAck id=0xc8 <asyncmap 0x0> <magic 0xab132318> <pcomp> <accomp>]

So far, so good.

> Oct 20 13:56:12  pppd[5792]: rcvd [LCP ConfAck id=0xc8 <asyncmap 0x0> <magic 0xd71a0c90> <pcomp> <accomp>]

Uh oh.  It looks like the peer is broken.  Note the ID number on that
message: it's 0xc8.  That's the ID on the peer's own Configure-Request,
which makes no sense at all.

The peer should be echoing back the ID on the Configure-Request that we
sent.  That message had ID set to 0xc9.  The IDs are completely
independent in each direction; our choice in our Configure-Request has
nothing to do with his choice in his Configure-Request.

In other words, the peer has a bug.  Because of this bug, we will (per
RFC 1661) discard that LCP Configure-Ack message as malformed, and stay
in state Ack-Sent.

> Oct 20 13:56:12  pppd[5792]: rcvd [LCP EchoReq id=0x0 magic=0xab132318]
> Oct 20 13:56:12  pppd[5792]: rcvd [LCP EchoRep id=0x0 magic=0xab132318]
> Oct 20 13:56:12  pppd[5792]: rcvd [CCP ConfReq id=0xc8 <deflate 15> <deflate(old#) 15>]
> Oct 20 13:56:12  pppd[5792]: Discarded non-LCP packet when LCP not open

This happens because the peer thinks LCP is done, but it's not.

> Oct 20 13:56:14  pppd[5792]: sent [LCP ConfReq id=0xc9 <asyncmap 0x0> <magic 0xf79dba92> <pcomp> <accomp>]

Our restart timer goes off, which is event TO+.  We stay in Ack-Sent
state, and send a new LCP Configure-Request message.

> Oct 20 13:56:15  pppd[5792]: rcvd [LCP ConfReq id=0xc9 <asyncmap 0x0> <magic 0xb84a827a> <pcomp> <accomp>]
> Oct 20 13:56:15  pppd[5792]: sent [LCP ConfAck id=0xc9 <asyncmap 0x0> <magic 0xb84a827a> <pcomp> <accomp>]
> Oct 20 13:56:15  pppd[5792]: rcvd [LCP ConfAck id=0xc9 <asyncmap 0x0> <magic 0xf79dba92> <pcomp> <accomp>]

It looks like everything works out at this point.  LCP goes to Opened
state, and we start bringing up the NCPs.

> Oct 20 13:56:18  pppd[5792]: rcvd [LCP ConfReq id=0xc9 <asyncmap 0x0> <magic 0xb84a827a> <pcomp> <accomp>]

The peer resends his Configure-Request.  He evidently got stuck in
Ack-Sent state himself, because he misconstrued our Configure-Request
message.

Oh well.  Fix or replace the peer.  It's broken.

-- 
James Carlson         42.703N 71.076W         <carlsonj@workingcode.com>

Re: strange pppd error

[James Carlson]

I should always proof-read before sending.  :-/

James Carlson wrote:
> walter harms wrote:
>> Oct 20 13:56:12  pppd[5792]: rcvd [LCP ConfReq id=0xc8 <asyncmap 0x0> <magic 0xab132318> <pcomp> <accomp>]
>> Oct 20 13:56:12  pppd[5792]: sent [LCP ConfReq id=0xc9 <asyncmap 0x0> <magic 0xf79dba92> <pcomp> <accomp>]
>> Oct 20 13:56:12  pppd[5792]: sent [LCP ConfAck id=0xc8 <asyncmap 0x0> <magic 0xab132318> <pcomp> <accomp>]
>> Oct 20 13:56:12  pppd[5792]: rcvd [LCP ConfAck id=0xc8 <asyncmap 0x0> <magic 0xd71a0c90> <pcomp> <accomp>]
> 
> Uh oh.  It looks like the peer is broken.  Note the ID number on that
> message: it's 0xc8.  That's the ID on the peer's own Configure-Request,
> which makes no sense at all.

One other clue I certainly should have noticed here is the magic number
-- it's different from what we sent.  So that is *not* merely an errant
response on the peer's part.

Why is the peer sending that last message above?  I don't know.  It's as
though the peer is responding to an LCP Configure-Request that we never
sent, at least according to the abbreviated log file presented here.

(You don't need to post the whole multi-megabyte log file, but posting
the LCP initial negotiation on the link and any LCP negotiation messages
seen up to the point of failure would be extremely helpful.)

What's the nature of the link between these two systems?  Is it possible
for LCP messages from one link to be replayed on another link?  Is it
possible for some other machine's messages to get injected on this link?
 Could the link itself store and replay messages?

I think the first step would be finding out why the peer suddenly
thought it received an LCP Configure-Request message from us with ID
0xc8 and Magic Number 0xd71a0c90, when we apparently sent no such thing.

-- 
James Carlson         42.703N 71.076W         <carlsonj@workingcode.com>

Re: strange pppd error

[walter harms]

James Carlson schrieb:
> I should always proof-read before sending.  :-/
> 
> James Carlson wrote:
>> walter harms wrote:
>>> Oct 20 13:56:12  pppd[5792]: rcvd [LCP ConfReq id=0xc8 <asyncmap 0x0> <magic 0xab132318> <pcomp> <accomp>]
>>> Oct 20 13:56:12  pppd[5792]: sent [LCP ConfReq id=0xc9 <asyncmap 0x0> <magic 0xf79dba92> <pcomp> <accomp>]
>>> Oct 20 13:56:12  pppd[5792]: sent [LCP ConfAck id=0xc8 <asyncmap 0x0> <magic 0xab132318> <pcomp> <accomp>]
>>> Oct 20 13:56:12  pppd[5792]: rcvd [LCP ConfAck id=0xc8 <asyncmap 0x0> <magic 0xd71a0c90> <pcomp> <accomp>]
>> Uh oh.  It looks like the peer is broken.  Note the ID number on that
>> message: it's 0xc8.  That's the ID on the peer's own Configure-Request,
>> which makes no sense at all.
> 
> One other clue I certainly should have noticed here is the magic number
> -- it's different from what we sent.  So that is *not* merely an errant
> response on the peer's part.
> 
> Why is the peer sending that last message above?  I don't know.  It's as
> though the peer is responding to an LCP Configure-Request that we never
> sent, at least according to the abbreviated log file presented here.
> 
> (You don't need to post the whole multi-megabyte log file, but posting
> the LCP initial negotiation on the link and any LCP negotiation messages
> seen up to the point of failure would be extremely helpful.)
> 
> What's the nature of the link between these two systems?  Is it possible
> for LCP messages from one link to be replayed on another link?  Is it
> possible for some other machine's messages to get injected on this link?
>  Could the link itself store and replay messages?
> 
> I think the first step would be finding out why the peer suddenly
> thought it received an LCP Configure-Request message from us with ID
> 0xc8 and Magic Number 0xd71a0c90, when we apparently sent no such thing.
> 

thx for your fast response.

These are the first entries in the log. The link between the system is
an ordinary    "modem <- phoneline -> modem"    connection. there is nothing
in between (except the telco stuff of cause).

btw: I have noticed that the  "ConfReq id" simply wraps at 255 would it be useful to
have a patch that breaks the connection instead of continue counting ?

re,
 wh


Oct 20 11:24:32  pppd[5792]: pppd 2.4.2b3 started by root, uid 0
Oct 20 11:25:00  pppd[5792]: Serial connection established.
Oct 20 11:25:00  pppd[5792]: using channel 59
Oct 20 11:25:00  pppd[5792]: Using interface ppp0
Oct 20 11:25:00  pppd[5792]: Connect: ppp0 <--> /dev/modem
Oct 20 11:25:01  pppd[5792]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
Oct 20 11:25:09  pppd[5792]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
Oct 20 11:25:09  pppd[5792]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
Oct 20 11:25:09  pppd[5792]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
Oct 20 11:25:10  pppd[5792]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
Oct 20 11:25:10  pppd[5792]: sent [LCP EchoReq id=0x0 magic=0xb655033a]
Oct 20 11:25:10  pppd[5792]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 10.0.0.2>]
Oct 20 11:25:12  pppd[5792]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
Oct 20 11:25:12  pppd[5792]: sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
Oct 20 11:25:12  pppd[5792]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
Oct 20 11:25:14  pppd[5792]: sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
Oct 20 11:25:14  pppd[5792]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
Oct 20 11:25:14  pppd[5792]: rcvd [LCP EchoReq id=0x0 magic=0xb426be22]
Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
Oct 20 11:25:14  pppd[5792]: sent [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
Oct 20 11:25:14  pppd[5792]: sent [LCP EchoReq id=0x0 magic=0x908697da]
Oct 20 11:25:14  pppd[5792]: sent [IPCP ConfReq id=0x2 <compress VJ 0f 01> <addr 10.0.0.2>]
Oct 20 11:25:14  pppd[5792]: rcvd [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15>]
Oct 20 11:25:14  pppd[5792]: sent [CCP ConfReq id=0x1]
Oct 20 11:25:14  pppd[5792]: sent [CCP ConfRej id=0x1 <deflate 15> <deflate(old#) 15>]
Oct 20 11:25:14  pppd[5792]: rcvd [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0>]
Oct 20 11:25:14  pppd[5792]: sent [IPCP ConfNak id=0x1 <addr 10.0.0.1>]
Oct 20 11:25:17  pppd[5792]: sent [IPCP ConfReq id=0x2 <compress VJ 0f 01> <addr 10.0.0.2>]
Oct 20 11:25:17  pppd[5792]: sent [CCP ConfReq id=0x1]
Oct 20 11:25:17  pppd[5792]: rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
Oct 20 11:25:17  pppd[5792]: sent [LCP ConfReq id=0x3 <asyncmap 0x0> <magic 0x7614dc03> <pcomp> <accomp>]
Oct 20 11:25:17  pppd[5792]: sent [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
Oct 20 11:25:17  pppd[5792]: rcvd [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
Oct 20 11:25:17  pppd[5792]: rcvd [LCP EchoReq id=0x0 magic=0x8e9f9ca2]
Oct 20 11:25:17  pppd[5792]: rcvd [LCP EchoRep id=0x0 magic=0x8e9f9ca2]
Oct 20 11:25:17  pppd[5792]: rcvd [CCP ConfReq id=0x2 <deflate 15> <deflate(old#) 15>]
Oct 20 11:25:17  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 11:25:17  pppd[5792]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f 01> <addr 0.0.0.0>]
Oct 20 11:25:17  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 11:25:17  pppd[5792]: rcvd [IPCP ConfAck id=0x2 <compress VJ 0f 01> <addr 10.0.0.2>]
Oct 20 11:25:17  pppd[5792]: Discarded non-LCP packet when LCP not open
Oct 20 11:25:17  pppd[5792]: rcvd [CCP ConfAck id=0x1]

Re: strange pppd error

[James Carlson]

walter harms wrote:
> These are the first entries in the log. The link between the system is
> an ordinary    "modem <- phoneline -> modem"    connection. there is nothing
> in between (except the telco stuff of cause).

OK.  That certainly rules out a number of possibilities.  The new logs
help even more.

> btw: I have noticed that the  "ConfReq id" simply wraps at 255 would it be useful to
> have a patch that breaks the connection instead of continue counting ?

I can't imagine why you'd want to do that.  The ID number is _designed_
to roll over.  (In fact, it's completely ephemeral and needn't be
sequential at all.  All that's really needed for the protocol to work is
that the ID for unique messages is chosen so that identical IDs are
repeated as infrequently as possible.  It turns out that a simple
wrap-around increment does that just fine, but *any* such sequence
serves the purpose for the protocol requirements.)

> Oct 20 11:25:01  pppd[5792]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
> Oct 20 11:25:09  pppd[5792]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
> Oct 20 11:25:09  pppd[5792]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
> Oct 20 11:25:09  pppd[5792]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
> Oct 20 11:25:10  pppd[5792]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]

That looks good.  We send Configure-Request ID 1, and he acks it, and we
ack his request as well.

> Oct 20 11:25:12  pppd[5792]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]

That doesn't look so good.  The peer is retransmitting its LCP
Configure-Request, and it's unclear why it's doing that.  We've already
sent an ack.

The standard state machine doesn't support what this peer is doing.  I
suppose that if it somehow missed our Configure-Ack (how?), this could
be a valid thing to do.  But the question is how it could have missed
that message, when it just recently sent us Configure-Request.

Something odd is going on here.

> Oct 20 11:25:12  pppd[5792]: sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
> Oct 20 11:25:12  pppd[5792]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]

We behave as the standards require; jumping back to Ack-Sent state.

> Oct 20 11:25:14  pppd[5792]: sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]

The peer hasn't responded.  We try again by resending Configure-Request.
 It's odd that we're retrying in just 2 seconds.  The default is 3.
Have you tweaked your configuration?

> Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
> Oct 20 11:25:14  pppd[5792]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]

The peer sends us a new Configure-Request by itself.  Why he does this
is unclear.  It looks like his restart timer went off, but why didn't he
respond to either of the two Configure-Requests we've sent?

> Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
> Oct 20 11:25:14  pppd[5792]: sent [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
> Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
> Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]

He finally responds, but there's a problem here.  Note the first of
those two received Configure-Ack messages: it's ID 1.  He's actually
sending a duplicate Configure-Ack.  That's not a terribly legitimate
thing to do; he shouldn't be resending Configure-Ack at all.  The
standards don't support it.

As for the second Configure-Ack received above, it looks like there are
occasional long delays on this link, which wouldn't be surprising with a
modem.  I think you need to set at least "lcp-restart 3" or perhaps
higher, if this link is subject to lengthy delays.  Having a too-short
restart timer can cause all sorts of unwanted behavior.

> Oct 20 11:25:17  pppd[5792]: rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
> Oct 20 11:25:17  pppd[5792]: sent [LCP ConfReq id=0x3 <asyncmap 0x0> <magic 0x7614dc03> <pcomp> <accomp>]
> Oct 20 11:25:17  pppd[5792]: sent [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
> Oct 20 11:25:17  pppd[5792]: rcvd [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]

What?  We sent only two Configure-Request messages with ID 0x2.  He sent
*THREE* Configure-Ack messages with ID 0x2!  That's not right.

I'm much more convinced now that the peer is junk.  It'll likely need
repair or replacement.

-- 
James Carlson         42.703N 71.076W         <carlsonj@workingcode.com>

Re: strange pppd error

[walter harms]

James Carlson schrieb:
> walter harms wrote:
>> These are the first entries in the log. The link between the system is
>> an ordinary    "modem <- phoneline -> modem"    connection. there is nothing
>> in between (except the telco stuff of cause).
> 
> OK.  That certainly rules out a number of possibilities.  The new logs
> help even more.
> 
>> btw: I have noticed that the  "ConfReq id" simply wraps at 255 would it be useful to
>> have a patch that breaks the connection instead of continue counting ?
> 
> I can't imagine why you'd want to do that.  The ID number is _designed_
> to roll over.  (In fact, it's completely ephemeral and needn't be
> sequential at all.  All that's really needed for the protocol to work is
> that the ID for unique messages is chosen so that identical IDs are
> repeated as infrequently as possible.  It turns out that a simple
> wrap-around increment does that just fine, but *any* such sequence
> serves the purpose for the protocol requirements.)
> 
>> Oct 20 11:25:01  pppd[5792]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
>> Oct 20 11:25:09  pppd[5792]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
>> Oct 20 11:25:09  pppd[5792]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
>> Oct 20 11:25:09  pppd[5792]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
>> Oct 20 11:25:10  pppd[5792]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
> 
> That looks good.  We send Configure-Request ID 1, and he acks it, and we
> ack his request as well.
> 
>> Oct 20 11:25:12  pppd[5792]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
> 
> That doesn't look so good.  The peer is retransmitting its LCP
> Configure-Request, and it's unclear why it's doing that.  We've already
> sent an ack.
> 
> The standard state machine doesn't support what this peer is doing.  I
> suppose that if it somehow missed our Configure-Ack (how?), this could
> be a valid thing to do.  But the question is how it could have missed
> that message, when it just recently sent us Configure-Request.
> 
> Something odd is going on here.
> 
>> Oct 20 11:25:12  pppd[5792]: sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
>> Oct 20 11:25:12  pppd[5792]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
> 
> We behave as the standards require; jumping back to Ack-Sent state.
> 
>> Oct 20 11:25:14  pppd[5792]: sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
> 
> The peer hasn't responded.  We try again by resending Configure-Request.
>  It's odd that we're retrying in just 2 seconds.  The default is 3.
> Have you tweaked your configuration?

good idea (it was some time ago since the files where touched :)
i found the following:

lcp-echo-interval 30
lcp-echo-failure 4
lcp-max-configure 60
lcp-restart 2




> 
>> Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
>> Oct 20 11:25:14  pppd[5792]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb426be22> <pcomp> <accomp>]
> 
> The peer sends us a new Configure-Request by itself.  Why he does this
> is unclear.  It looks like his restart timer went off, but why didn't he
> respond to either of the two Configure-Requests we've sent?
> 
>> Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
>> Oct 20 11:25:14  pppd[5792]: sent [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
>> Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xb655033a> <pcomp> <accomp>]
>> Oct 20 11:25:14  pppd[5792]: rcvd [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
> 
> He finally responds, but there's a problem here.  Note the first of
> those two received Configure-Ack messages: it's ID 1.  He's actually
> sending a duplicate Configure-Ack.  That's not a terribly legitimate
> thing to do; he shouldn't be resending Configure-Ack at all.  The
> standards don't support it.
> 
> As for the second Configure-Ack received above, it looks like there are
> occasional long delays on this link, which wouldn't be surprising with a
> modem.  I think you need to set at least "lcp-restart 3" or perhaps
> higher, if this link is subject to lengthy delays.  Having a too-short
> restart timer can cause all sorts of unwanted behavior.
> 
>> Oct 20 11:25:17  pppd[5792]: rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
>> Oct 20 11:25:17  pppd[5792]: sent [LCP ConfReq id=0x3 <asyncmap 0x0> <magic 0x7614dc03> <pcomp> <accomp>]
>> Oct 20 11:25:17  pppd[5792]: sent [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
>> Oct 20 11:25:17  pppd[5792]: rcvd [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
> 
> What?  We sent only two Configure-Request messages with ID 0x2.  He sent
> *THREE* Configure-Ack messages with ID 0x2!  That's not right.
> 
> I'm much more convinced now that the peer is junk.  It'll likely need
> repair or replacement.
> 

yep, i have already scheduled that ppp 2.4.4 is need.
NTL it should be noted there is bug hidden that can cause some
funny phone bills (believe me). But it seems the distro have all
there own version can you recommend a source ?

re,
 wh

Re: strange pppd error

[James Carlson]

walter harms wrote:
> James Carlson schrieb:
>>> Oct 20 11:25:14  pppd[5792]: sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
>> The peer hasn't responded.  We try again by resending Configure-Request.
>>  It's odd that we're retrying in just 2 seconds.  The default is 3.
>> Have you tweaked your configuration?
> 
> good idea (it was some time ago since the files where touched :)
> i found the following:
> 
> lcp-echo-interval 30
> lcp-echo-failure 4
> lcp-max-configure 60
> lcp-restart 2

That would do it.  Do you know for a fact that at least the last two of
those are necessary?  In general, it's not a good idea to change options
away from the defaults unless there's a very specific need.

In the case of "lcp-max-configure," that's an oft-misunderstood option.
 If you get the "too many configure requests" failure message, it almost
always means that something _else_ is wrong, and users mistakenly reach
for this tunable to "fix" things.  Instead, this is very rarely needed,
and it's used to work around bugs that cause active negotiation (with
different options tried at each stage) to take a long time to converge.

The "lcp-restart" setting is worrying.  You want this to be longer if
the maximum delay on the link is longer.  I certainly wouldn't set it
shorter than the default of 3 seconds for any modem link, and I'd
consider making it longer.  Having it too short means that we'll send
new Configure-Request messages when we don't absolutely need to, and
this can easily provoke latent bugs in some peers.

I suggest either:

  - removing both options,

or

  - removing the lcp-max-configure option and changing lcp-restart to
    be 4 or larger.

>>> Oct 20 11:25:17  pppd[5792]: rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
>>> Oct 20 11:25:17  pppd[5792]: sent [LCP ConfReq id=0x3 <asyncmap 0x0> <magic 0x7614dc03> <pcomp> <accomp>]
>>> Oct 20 11:25:17  pppd[5792]: sent [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x8e9f9ca2> <pcomp> <accomp>]
>>> Oct 20 11:25:17  pppd[5792]: rcvd [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0x908697da> <pcomp> <accomp>]
>> What?  We sent only two Configure-Request messages with ID 0x2.  He sent
>> *THREE* Configure-Ack messages with ID 0x2!  That's not right.
>>
>> I'm much more convinced now that the peer is junk.  It'll likely need
>> repair or replacement.
>>
> 
> yep, i have already scheduled that ppp 2.4.4 is need.
> NTL it should be noted there is bug hidden that can cause some
> funny phone bills (believe me). But it seems the distro have all
> there own version can you recommend a source ?

I recommend dealing with the upstream vendor first.  I don't know what
that embedded system peer is running, but if it's actually running pppd,
then that's suspicious, because it shouldn't be that far away from the
standard even if it is out of date.

If it is running pppd, and if you really do want to try rolling your own
copy, then start with:

  ftp://ftp.samba.org/pub/ppp/ppp-2.4.4.tar.gz

-- 
James Carlson         42.703N 71.076W         <carlsonj@workingcode.com>