Re: [lwip-users] Weird PPP behavior

[Gennady Shmakov]

Hi, 

I've got to the root of this problem.

Sergio, Patrick, thank you for suggesting looking at the byte stream. It helped a lot to solve it.

I had a problem in usb stack code.

Some junk bytes were fed to ppp from previous usb transaction and that caused wrong checksum and entire lcp negotiation failure.

I'm testing it now for a few hours and several hundreds connection-disconnection cycles and everything works fine now.

Thanks again.

-----
Regards,
Gennady
mob. +7 985 8181210

On Wed, Mar 2, 2016 at 6:23 PM, Patrick Klos <address@hidden> wrote:

On 2/29/2016 8:55 AM, Gennady Shmakov wrote:

Sylvain,

Thank you very much for looking at it.

 

I'm a little worried about wrong checksum:

> pppos_input[0]: got 44 bytes

> pppos_input[0]: got 61 bytes
> pppos_input[0]: Dropping bad fcs 0x9e4f proto=0xc021
> pppos_input_drop: pbuf len=21, addr 2001afe8

I've compared log with bad fcs with log when everything goes fine.

In "ok" log I dont see extra 44 bytes at pppos_input at this point:

> pppos_input[0]: got 44 bytes

I've double checked my driver code to make sure I dont mistakenly throw any garbage to pppos_input_tcpip from USB stack.

And driver code looks ok. So seems like modem sends something lwip does not expect.

Can you share with us the exact byte stream to and from the USB modem? (with timing?)

Line 35 of ppp_dbg_err.txt implies the peer did not see your LCP ConfigAck (line 24) so it's sending the LCP ConfigRequest again (even though you moved on the the authenticate stage).  That SHOULD drop your state machine back to LCP negotiating (which it looks like is happening - so far, so good).

On line 42, you resend your LCP ConfigRequest, and on line 44, you set an LCP ConfigAck.

What I don't see between lines 44 and 47 (where you receive a PAP AuthenticateAck from the USB modem) is an LCP ConfigAck for your LCP ConfigRequest, which is why your side is (correctly) discarding the PAP messages.

Further on, the USB modem sends you an LCP ConfigNak for id=0x2 with no options - that's not valid.  A ConfigNak is supposed to contain the options that are being NAKed from the ConfigRequest.

On line 75, both sides should finally reach the LCP Opened state.

On line 82, you send the PAP AuthenticateRequest, and on line 87, the USB modem sends back a PAP AuthenticateAck (despite the interim LCP ConfigAck).

You then go on to try to negotiate IPCP.

One thing that sticks out at me is the message on line 94:

sent [IPCP ConfNak id=0x1 <addr 0.0.0.Àpppos_input[0]: got 28 bytes

It looks like 2 log lines got munged together, which, to me, indicates that possibly 2 threads are trying to write to the log at the same time?  Is it possible that 2 threads (or foreground and interrupt) are trying to do work in the PPP stack at the same time?

Line 101 receives an IPCP ConfigNak for id=0x3, but there was no IPCP ConfigRequest with a matching id shown in the log.

It falls apart from there...

I still think the actual byte stream may shed some light on what might be happening??

Patrick Klos
Klos Technologies, Inc.

_______________________________________________
lwip-users mailing list
address@hidden
https://lists.nongnu.org/mailman/listinfo/lwip-users