strange pppd error

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>

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

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.

So far, so good.

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.

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

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

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

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         <[email protected]>

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

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         <[email protected]>

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]

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

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.)

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

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.

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

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?

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?

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.

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         <[email protected]>

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

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

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.

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         <[email protected]>