Re: [lwip-users] PPPoS: ppp session disconnect if hit bad fcs for LCP packet

[Patrick Klos]

On 7/15/2017 10:45 AM, Axel Lin wrote:
> Hi Patrick,
> I found a strange pattern (it happens 3 times)

Does it always involve the loss of 63 bytes each time? (you'll 
understand why I'm asking after reading the rest of my response)

> IP total length is 430 (0x1ae) but I got pbuf len=371.
> I'm wondering if it lost some packet, why it always happened whith
> pppos_input_drop: pbuf len=371.
>
> Below is part of my debug log:
>
> pppos_netif_output[0]: proto=0x21, len = 544

That message must have been from the previous outgoing packet?

> 2145000028767f4000ee0625693640ae650a0002420050f3cf6ca5a3780091d03d50106ce07d5d0000006f7c7e21450001ae76804000ee0623e23640ae650a0002420050f3cf6ca5a3780091d03d50186ce05bc00000485454502f312e31

It seems some debug lines are possibly missing?  I would have expected a 
"pppos_input[0]: got 94 bytes" before that line (above).

> ppp_input[0]: ip in pbuf len=40

That makes sense.  First IP packet:

45 00 00 28 76 7f 40 00 ee 06 25 69 36 40 ae 65
0a 00 02 42 00 50 f3 cf 6c a5 a3 78 00 91 d0 3d
50 10 6c e0 7d 00 00 00

Followed by the first 49 bytes of the next packet:

21
45 00 01 ae 76 80 40 00 ee 06 23 e2 36 40 ae 65
0a 00 02 42 00 50 f3 cf 6c a5 a3 78 00 91 d0 3d
50 18 6c e0 5b c0 00 00 48 54 54 50 2f 31 2e 31

(note that one of the bytes was ESCAPEd)

> pppos_input[0]: got 256 bytes
> 20323030204f4b0d0a43616368652d433a205361742c203135204a756c20323031372030383a32303a313920474d540d0a5365727665723a206e67696e782f312e382e310d0a5365742d436f6f6b69653a20726571756573745f6d6574686f643d504f53543b20706174683d2f0d0a582d436f6e74656e742d547970652d4f7074696f6e733a206e6f736e6966660d0a582d4672616d652d4f7074696f6e733a2053414d454f524947494e0d0a582d526571756573742d49643a2038333633633334352d373038612d343634362d393562662d6462356338623061366534300d0a582d52756e74696d653a20302e3030353731370d0a582d5853532d50726f74

The next 256 bytes of the packet:

20 32 30 30 20 4f 4b 0d 0a 43 61 63 68 65 2d 43
3a 20 53 61 74 2c 20 31 35 20 4a 75 6c 20 32 30
31 37 20 30 38 3a 32 30 3a 31 39 20 47 4d 54 0d
0a 53 65 72 76 65 72 3a 20 6e 67 69 6e 78 2f 31
2e 38 2e 31 0d 0a 53 65 74 2d 43 6f 6f 6b 69 65
3a 20 72 65 71 75 65 73 74 5f 6d 65 74 68 6f 64
3d 50 4f 53 54 3b 20 70 61 74 68 3d 2f 0d 0a 58
2d 43 6f 6e 74 65 6e 74 2d 54 79 70 65 2d 4f 70
74 69 6f 6e 73 3a 20 6e 6f 73 6e 69 66 66 0d 0a
58 2d 46 72 61 6d 65 2d 4f 70 74 69 6f 6e 73 3a
20 53 41 4d 45 4f 52 49 47 49 4e 0d 0a 58 2d 52
65 71 75 65 73 74 2d 49 64 3a 20 38 33 36 33 63
33 34 35 2d 37 30 38 61 2d 34 36 34 36 2d 39 35
62 66 2d 64 62 35 63 38 62 30 61 36 65 34 30 0d
0a 58 2d 52 75 6e 74 69 6d 65 3a 20 30 2e 30 30
35 37 31 37 0d 0a 58 2d 58 53 53 2d 50 72 6f 74


So far, looks reasonable.

> pppos_input[0]: got 110 bytes
> 656374696f6e3a20313b206d6f64653d626c6f636b0d0a436f6e74656e742d4c656e6774683a20300d0a436f6e6e656374696f6e3a20436c6f73650d0a0d0ada2a7e214500002876814000ee0625673640ae650a0002420050f3cf6ca5a4fe0091d03d50116ce07b7900003c297e

This buffer contains the next 63 bytes of the packet, plus the FCS (and 
FLAG):

65 63 74 69 6f 6e 3a 20 31 3b 20 6d 6f 64 65 3d
62 6c 6f 63 6b 0d 0a 43 6f 6e 74 65 6e 74 2d 4c
65 6e 67 74 68 3a 20 30 0d 0a 43 6f 6e 6e 65 63
74 69 6f 6e 3a 20 43 6c 6f 73 65 0d 0a 0d 0a

FCS: da 2a

7e (FLAG)

> pppos_input[0]: Dropping bad fcs 0xc532 proto=0x21

OK.  That is the computed FCS for the packet data of the completed 
packet.  Clearly, your system lost 63 bytes someplace.

Followed by another complete IP packet:

21
45 00 00 28 76 81 40 00 ee 06 25 67 36 40 ae 65
0a 00 02 42 00 50 f3 cf 6c a5 a4 fe 00 91 d0 3d
50 11 6c e0 7b 79 00 00

FCS: 3c29

7e (FLAG)

> pppos_input_drop: pbuf len=371, addr 0x2000fd04
>
>
> pppos_input[0]: got 8 bytes
> 2145000028016a40

First 8 bytes of next packet.

> pppos_input[0]: got 172 bytes
> 00ee069a7d5e3640ae650a0002420050d937400928a901dad37350106cfc3a69000043707e21450001ae016b4000ee0698f73640ae650a0002420050d937400928a901dad37350186cfcaf250000485454502f312e3120323030204f4b0d0a43616368652d433a205361742c203135204a756c20323031372031303a31393a343420474d540d0a5365727665723a206e67696e782f312e382e310d0a5365742d436f6f6b69653a2072657175

Next bunch of bytes for the 40 byte IP packet (including protocol byte, 
1 ESCAPEd character, and FCS).

> ppp_input[0]: ip in pbuf len=40


> pppos_input[0]: got 256 bytes
> 6573745f6d6574686f643d504f53543b20706174683d2f0d0a582d436f6e74656e742d547970652d4f7074696f6e733a206e6f736e6966660d0a582d4672616d652d4f7074696f6e733a2053414d454f524947494e0d0a582d526571756573742d49643a2038646230646539662d343734302d343936362d396337332d3337336565316538366166630d0a582d52756e74696d653a20302e3030313538300d0a582d5853532d50726f74656374696f6e3a20313b206d6f64653d626c6f636b0d0a436f6e74656e742d4c656e6774683a20300d0a436f6e6e656374696f6e3a20436c6f73650d0a0d0a1bd97e2145000028016c4000ee069a7c3640ae650a0002

More bytes, including 235 bytes for the existing packet, plus 20 bytes 
for the following packet.

> pppos_input[0]: Dropping bad fcs 0xa809 proto=0x21

Again, the computed FCS is correct for the collected data.  You lost 63 
bytes again.

> pppos_input_drop: pbuf len=371, addr 0x2000f68c

Let me ask a question: what kind of serial controller are you using to 
collect the bytes from the serial line?  What size is the FIFO in the 
serial controller?  If it's 64 bytes, then I would suggest you check the 
possibility that you're losing an interrupt from the serial controller.

Patrick Klos
Klos Technologies, Inc.