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

[Axel Lin]

Hi Patrick,

2017-07-16 9:20 GMT+08:00 Patrick Klos <address@hidden>:
> 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)

I grep my recent logs, all of this happens with pbuf len=371:

log1:[2017-07-13 07:52:57.280] pppos_input[0]: Dropping bad fcs 0x681e
proto=0x21
log1-[2017-07-13 07:52:57.281] pppos_input_drop: pbuf len=371, addr 0x2000fd04

log2:[2017-07-14 01:00:37.982] pppos_input[0]: Dropping bad fcs 0xf529
proto=0x21
log2-[2017-07-14 01:00:37.988] pppos_input_drop: pbuf len=371, addr 0x2000fd04

log2:[2017-07-14 07:26:17.535] pppos_input[0]: Dropping bad fcs 0xa718
proto=0x21
log2-[2017-07-14 07:26:17.541] pppos_input_drop: pbuf len=371, addr 0x2000e99c

log3:[2017-07-15 01:22:03.331] pppos_input[0]: Dropping bad fcs 0x27ef
proto=0x21
log3-[2017-07-15 01:22:03.338] pppos_input_drop: pbuf len=371, addr 0x2000c2cc

log3:[2017-07-15 03:54:10.370] pppos_input[0]: Dropping bad fcs 0x5442
proto=0x21
log3-[2017-07-15 03:54:10.375] pppos_input_drop: pbuf len=371, addr 0x2000c2cc

log3:[2017-07-15 04:00:07.154] pppos_input[0]: Dropping bad fcs 0x8d7c
proto=0x21
log3-[2017-07-15 04:00:07.159] pppos_input_drop: pbuf len=371, addr 0x2000e324

log3:[2017-07-15 05:36:05.534] pppos_input[0]: Dropping bad fcs 0x7220
proto=0x21
log3-[2017-07-15 05:36:05.539] pppos_input_drop: pbuf len=371, addr 0x2001037c

log3:[2017-07-15 06:04:55.906] pppos_input[0]: Dropping bad fcs 0xfd0c
proto=0x21
log3-[2017-07-15 06:04:55.911] pppos_input_drop: pbuf len=371, addr 0x2000e324

log3:[2017-07-15 12:41:07.380] pppos_input[0]: Dropping bad fcs 0xab24
proto=0x21
log3-[2017-07-15 12:41:07.385] pppos_input_drop: pbuf len=371, addr 0x2000c2cc

log3:[2017-07-15 15:29:04.414] pppos_input[0]: Dropping bad fcs 0xb17 proto=0x21
log3-[2017-07-15 15:29:04.420] pppos_input_drop: pbuf len=371, addr 0x200109f4

log3:[2017-07-15 16:20:19.617] pppos_input[0]: Dropping bad fcs 0xc532
proto=0x21
log3-[2017-07-15 16:20:19.623] pppos_input_drop: pbuf len=371, addr 0x2000fd04

log3:[2017-07-15 18:19:44.484] pppos_input[0]: Dropping bad fcs 0xa809
proto=0x21
log3-[2017-07-15 18:19:44.491] pppos_input_drop: pbuf len=371, addr 0x2000f68c

log5:[2017-07-16 04:52:22.654] pppos_input[0]: Dropping bad fcs 0x34eb
proto=0x21
log5-[2017-07-16 04:52:22.659] pppos_input_drop: pbuf len=371, addr 0x2000f68c

log5:[2017-07-16 06:39:42.442] pppos_input[0]: Dropping bad fcs 0x5800
proto=0x21
log5-[2017-07-16 06:39:42.446] pppos_input_drop: pbuf len=371, addr 0x2000f014

log7:[2017-07-16 14:06:24.335] pppos_input[0]: Dropping bad fcs 0x3a68
proto=0x21
log7-[2017-07-16 14:06:24.340] pppos_input_drop: pbuf len=371, addr 0x2000cfbc

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

I'm running on a STM32F4 platform.

The driver uses  below settings:

    /* Fill init structure with common DMA settings */
    dma_init_structure.DMA_PeripheralInc   = DMA_PeripheralInc_Disable;
    dma_init_structure.DMA_MemoryInc       = DMA_MemoryInc_Enable;
    dma_init_structure.DMA_Priority        = DMA_Priority_VeryHigh;
    dma_init_structure.DMA_FIFOMode        = DMA_FIFOMode_Disable;
    dma_init_structure.DMA_FIFOThreshold   = DMA_FIFOThreshold_Full;
    dma_init_structure.DMA_MemoryBurst     = DMA_MemoryBurst_Single;
    dma_init_structure.DMA_PeripheralBurst = DMA_PeripheralBurst_Single;

    /* Initialise RX DMA */
    DMA_DeInit( peripheral->rx_dma_config.stream );
    dma_init_structure.DMA_Channel            =
peripheral->rx_dma_config.channel;
    dma_init_structure.DMA_PeripheralBaseAddr = (uint32_t)
&peripheral->port->DR;
    dma_init_structure.DMA_Memory0BaseAddr    = 0;
    dma_init_structure.DMA_DIR                = DMA_DIR_PeripheralToMemory;
    dma_init_structure.DMA_BufferSize         = 0xFFFF;
     // This parameter will be configured during communication
    dma_init_structure.DMA_Mode               = DMA_Mode_Normal;
    DMA_Init( peripheral->rx_dma_config.stream, &dma_init_structure );

    driver->peripheral->rx_dma_config.stream->NDTR  = size; // 4096
    driver->peripheral->rx_dma_config.stream->M0AR  = (uint32_t)data;
    driver->peripheral->rx_dma_config.stream->CR   |= DMA_SxCR_EN;
    USART_DMACmd( driver->peripheral->port, USART_DMAReq_Rx, ENABLE );

The driver uses DMA with circular mode, (the buffer size is 4096).
I'm still not clear why always lost 63 chars.
But it looks like not lwip problem but uart driver problem.

Thanks for your informative comments.

Regards,
Axel