This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

Why does LWIP 1.4.1 appear to skip freeing (p != NULL) when queued RX PBUF have no http response from Cloud.

Guru 56358 points

LWIP and tiva-tm4c129.c NETIF abstraction layer frees PBUF during RX frame process and or after the packet data is transferred up the layers to the application. ASSERT_FAIL does not always indicate we have a failure and at times is an informative message as to what is going on in LWIP such as LWIP_TRACE. Here we choose to name the LWIP debug message print out ASSERT_DEBUG. 

What if the expected RX frame queued PBUF is never RX back in the http response to the client or is invalid http header data format? The Ethernet client issues (pbuf_free(p)) and LWIP ASSERT checks if  (p != NULL) and simply returns as the PBUF is believed NULL. Appears like a slow memory leak and has been found to eventually fill the HEAP memory space almost to the maximum leaving very little space for allocating new PBUF in the abstraction layer. So we end up with a huge amount of PBUF broken chains without any pointers to them in SRAM (HEAP). Hence we can not clear the heap (mem_free) but only for the last few PBUF that may have been ok.

Application layer response to a queued PBUF for Payload of corrupted, missing or partial RX (http) header other than 204 response.

Upon subsequent pbuf_free() clear the corrected ASSERT PBUF pointer (p != NULL) returned. The confusion is if P=NULL we return and display Assert message only when ! p != NULL and still return 0 non the less if p = NULL. Presumably http 0 infers no ACK was returned from the host so then to the (Matching) ACK Pbuf is missing.

 exoHAL: << pcBuffer: Read Timeout >>
<< IOT Write (EXO_STATUS_END: Code 10 - http:0) >>
<< [Exosite_Write] No Response >>ASSERT_DEBUG at line 626 of C:/lwip-1.4.1/src/core/pbuf.c: p == NULL

Queued RX PBUF is perceived NULL. 


--- what say the LWIP group?

(pbuf.c):

pbuf_free(struct pbuf *p)
{
  u16_t type;
  struct pbuf *q;
  u8_t count;

  if (p == NULL) {
    LWIP_ASSERT("p != NULL", p != NULL); 
    /* if assertions are disabled, proceed with debug output */
    LWIP_DEBUGF(PBUF_DEBUG | LWIP_DBG_LEVEL_SERIOUS,
      ("pbuf_free(p == NULL) was called.\n"));
    return 0;
  }
 
  • We accelerated Systick TCP stack polling interval pushing the LWIP timers. So the very SLOW heap memory leak, case ASSERT (p != NULL) reveals itself in only a few days. TM4C 120mHz versus the 50mHz LM3S series MCU and the TCP stack respectfully accelerates data packet trough put. Case Adam Dunkels may need to test his LWIP1.4.1 a bit more thoroughly in all high speed EMAC DMA engines.

    Adjusted, ASSERT (p == NUL) finds (p->ref > 0) "All PBUF chains are referenced at least once" upon overflowing heap SRAM boundary. In so much (mem_free) backs down the PBUF overflow (time bomb) and MCU crash is temporary averted, until the RX descriptor chain is more heavily fragmented.
     
     Heap overflow has been there all along. Attempts to adjust (p->ref > 0 ) into (pbuf_free) call (if (p != NULL)) was futile. Seems the expected host ACK (http 204) Pbuf is not matched to the client Pbuf when it never sends a response, a  NAK is not replaced rather the host is RST.
     
    More confusing - LWIP_ASSERT (!) printf macro .

    MEM HEAP
    avail: 32768
    used: 25644
    max: 30496
    err: 0
    exoHAL: << pcBuffer: Read Timeout >>
    << IOT Write (EXO_STATUS_END: Code 10 - http:0) >>
    << [Exosite_Write] No Response >>
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    ASSERT_DEBUG p != NULL line:626  C:/lwip-1.4.1/src/core/pbuf.c
    
    later we get:
    
    ASSERT_DEBUG p->ref > 0 line 651  C:/lwip-1.4.1/src/core/pbuf.c: 
    >> RX NoBuffer Error <<
    
    MEM HEAP
    avail: 32768
    used: 29596
    max: 30828
    err: 814
    >> RX NoBuffer Error << Sent via (tiva-tm4c129.c)abstraction layer,
      can not allocate a single new PBUF for a new RX descriptor!
  • Seems PBUF chains or pointers to the chains are not always dereferenced or freed when the http header is not ACK. Our heap eventually over time highly fragments packed with broken DMA descriptor chains in SRAM. Although the (tiva pbuf trace) was not printing out in the debugF output it was enabled. Another LWIP_STATS fix is shown below that.

    Disable Pbuf debug and both (tivaif_trace_pbuf) inside (tiva-tm4c129.c) and set NETIF_DEBUG (lwipopts.h)

    #if NETIF_DEBUG //def
    /**
     * Dump the chain of pbuf pointers to the debug output.
     */
    void
    tivaif_trace_pbuf(const char *pcTitle, struct pbuf *p)
    {
        LWIP_DEBUGF(NETIF_DEBUG, ("%s %08x (%d, %d)", pcTitle, p, p->tot_len,
                    p->len));
    
        do
        {
            p = p->next;
            if(p)
            {
                LWIP_DEBUGF(NETIF_DEBUG, ("->%08x(%d)", p, p->len));
            }
            else
            {
                LWIP_DEBUGF(NETIF_DEBUG, ("->%08x", p));
            }
    
        } while((p != NULL) && (p->tot_len != p->len));
    
        LWIP_DEBUGF(NETIF_DEBUG, ("\n"));
    }
    #endif
    
    /**
     * This function is used to check whether a passed pbuf contains only buffers
     * resident in regions of memory that the Ethernet MAC can access.  If any
     * buffers in the chain are outside a DMA accessable section of physical memory,
     * the pbuf is copied to physical SRAM and a different pointer returned. If all
     * buffers are safe, the pbuf reference count is incremented and the original
     * pointer returned.
     */
    static struct pbuf *
    tivaif_check_pbuf(struct pbuf *p)
    {
        struct pbuf *pBuf;
        err_t Err;
    
        pBuf = p;
    
    #if NETIF_DEBUG //def
        tivaif_trace_pbuf("Original:", p);
    #endif
    
    #if NETIF_DEBUG //def
                        tivaif_trace_pbuf("Copied:", pBuf);
    #endif
    
    All the LINK_STATS rather are all TCP_STATS.
    
     TCP_STATS_INC(tcp.memerr);
    
     TCP_STATS_INC(tcp.drop);
    
    /* This is a good frame so pass it up the stack. */
     TCP_STATS_INC(tcp.recv);
    
    /* Update lwIP statistics */
     TCP_STATS_INC(tcp.xmit);
    

     

      
  • Case: >TCP_STATS_INC(tcp.drop);

    This case error message is Not showing dropped (frames/packets) at the EMAC as one might expect. We normally say no big deal must be Runts or Shorts yet the TCP (lenerr) packet length remains 0. By default Broadcasts and Multicasts become dropped packets in (tcp_in.c). The  (memerr) count follows the Listen PCB tcp_alloc shown at the bottom.

    Actually (packet) drops are occurring further up the layers in LWIP1.4.1. resulting from what might be random heap free block calculations gone amuck.

    The malloc heap (MEM_ALLIGNMENT) randomly becomes unstable LWIP 1.4.1 (mem.c) configured (opt.h) and or (lwipopts.h). The result of the random occurring unstable heap might be caused by retaining orphaned ACK's (tcp_in,c). To many unmatched ACK's (dropped frames & RST) results in the heap overflowing causing MCU exception faults. Why is mem_free not deallocating PBUF on the heap even with the faster memp_mem_malloc?

    Perhaps some answers to that question can be found in (mem.c).  

    MEM_LIBC_MALLOC  0 / MEMP_MEM_MALLOC  0,  MEMP_MEM_MALLOC 1 may at times run longer before heap fails. Either way ASSERT DEBUG (p != NULL) warning is not a good situation!

    TCP
    xmit: 57113
    recv: 11610
    fw: 0
    >>> drop: 57
    chkerr: 0
    lenerr: 0
    memerr: 813
    rterr: 0
    proterr: 57
    opterr: 0
    err: 0
    cachehit: 0
    
    (mem.c) heap ERROR LWIP_ASSERT("mem_malloc: allocated memory properly aligned.", ((mem_ptr_t)mem + SIZEOF_STRUCT_MEM) % MEM_ALIGNMENT == 0); LWIP_ASSERT("mem_malloc: sanity check alignment", (((mem_ptr_t)mem) & (MEM_ALIGNMENT-1)) == 0);

    /* If there is data which was previously "refused" by upper layer */ if (pcb->refused_data != NULL) { if ((tcp_process_refused_data(pcb) == ERR_ABRT) || ((pcb->refused_data != NULL) && (tcplen > 0))) { /* pcb has been aborted or refused data is still refused and the new segment contains data */ TCP_STATS_INC(tcp.drop);
       /* If no matching PCB was found, send a TCP RST (reset) to the
           sender. */
        LWIP_DEBUGF(TCP_RST_DEBUG, ("tcp_input: no PCB match found, resetting.\n"));
        if (!(TCPH_FLAGS(tcphdr) & TCP_RST)) {
          TCP_STATS_INC(tcp.proterr);
          TCP_STATS_INC(tcp.drop);
          tcp_rst(ackno, seqno + tcplen,
            ip_current_dest_addr(), ip_current_src_addr(),
            tcphdr->dest, tcphdr->src);
        }
        pbuf_free(p);
    #endif /* TCP_LISTEN_BACKLOG */
        npcb = tcp_alloc(pcb->prio);
        /* If a new PCB could not be created (probably due to lack of memory),
           we don't do anything, but rely on the sender will retransmit the
           SYN at a time when we have more memory available. */
        if (npcb == NULL) {
          LWIP_DEBUGF(TCP_DEBUG, ("tcp_listen_input: could not allocate PCB\n"));
          TCP_STATS_INC(tcp.memerr);
          return ERR_MEM;
        }

     

  • LWIP 1.4.1 the (TCP_TMR_INTERVAL 250ms) (tcp_impl.h) timer appears to fast for the faster TM4C application layer and can causes random exception 11 bus faults and or dropped frames in the EMAC. Depending on application code compiled instruction time totals (+delay) can extend bus faults occurring many hours or days. Buffer RX/TX blocking flags written into a macro (many instructions) seemingly are to slow. Things work much better replacing connection flag macros with simple Boolean flags. Far less frames are dropped establishing a remote connection keeping the initial heap small.
     
    Fix: Was not the TCP_TMR_INTERVAL causing dropped frames, explained in later posts. 

    TCP_TMR_INTERVAL    450ms /* The TCP timer interval in milliseconds. was 250ms*/

    #define TCP_FIN_WAIT_TIMEOUT          40000 /*4 seconds ;was milliseconds 20000*/
    #define TCP_SYN_RCVD_TIMEOUT       40000 /*4 seconds  ;was milliseconds 20000*/

    Systick (SYSCLK/100) 833ns or 1.2Mhz (*10)= 8.3us the LWIP interval timer polling (*100=833us IOT client tick) LWIP local timer interval cycle depending on HOST_TMR_INTERVAL  often 100 set in (lwipopts.h). Believe it or not the LWIP polling appears to fast at 8.3us and TCP timer drops RX frames believed without a matching PBUF.
     
    IOT Math: TCP interval timer 250ms*100 ticks = 25 ticks for every Systick LWIPtimer(10ms) or .010/25=400us TCP tick period. When TCP interval timer is  5ms*100=.5 or .010/.5 =20ms tick TCP timer period. Far better  is LWIPTimer(1) or 16.6us*500=8.3ms IOT client tick with a 16.6us LWIP click timer. The client then cleans up his PBUF pool issuing a pcb_free() after sending remote host RST request, since local client can't find a matching PCB. 
     
    Surprisingly a 250ms LWIP TCP timer interval may constrain the TCP WAIT for ACK period wait is to short @400us.  One reason for (p != NULL) could be the ACK WAIT period under runs creating orphaned frames @255ms TTL are somehow missed in expected PCB ACK period of the typical http 204 status returned from the host.   
      
    LWIPTimer(1)=5us 60KHz or (Systick(SYSCLK/2000) LWIP polling =16.6us interval:
    #define HOST_TMR_INTERVAL1                    1600   // (exoHAL +26.56ms LWIPtimer1)@(+16.6us LWIPLocalTimer1)
    #define HOST_TMR_INTERVAL2                       1    // (Telnet +16.6us LWIPtimer2)@(+16.6us LWIPLocalTimer2)

    Hidden response code is http:400 is the(p!=NULL)PBUF
    Shown above as << IOT Write(EXO_STATUS_END: Code 10 - http:0) >>
    
    << [Exosite_Write] Bad http response >>
    ASSERT_DEBUG: p != NULL line:623  C:/lwip-1.4.1/src/core/pbuf.c
    << IOT Write (EXO_STATUS_BAD_TCP: Code 5 - http:400) >>
    

  • 1. Checked over corrected the math and updated or added a few probable causes for the heap memory leak (p != NULL).
    2. Suggest the IOT client sending repeating RST to the host server every (http status = 0) causes the heap to grow unconstrained.
    3. Malloc - mem_free can not and does not seem to return the element memory space of an queued PCB waiting for an expected ACK that never arrives in the TIME_WAIT period, perhaps of the TCP coarse timer.
  • Good heap management during local network BW consumption at the switch port should be regulated by LWIP dropping PCB's sending RST. Also freeing the heap of any Queued ACK PCB expecting to return an http status to the remote host prior to sending an RST upon timeout.

    BTW: OOSEQ queued PBUF have a 3 second timeout and need to managed (periodically) put an element back in the pool when it is not used.

    EM HEAP
    avail: 32768
    used: 8580
    max: 9116
    err: 0
    
    MEM HEAP
    avail: 32768
    used: 10988
    max: 13044
    err: 0
    exoHAL: << pcBuffer: Read Timeout >>
    << IOT Write (EXO_STATUS_END: Code 10 - http:0) >>
    << [Exosite_Write] No Response >>
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    
    MEM HEAP
    avail: 32768
    used: 10348
    max: 13044
    err: 0
    exoHAL: << pcBuffer: Read Timeout >>
    << IOT Write (EXO_STATUS_END: Code 10 - http:0) >>
    << [Exosite_Write] No Response >>
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    
    MEM HEAP
    avail: 32768
    used: 9548
    max: 13044
    err: 0
    exoHAL: << pcBuffer: Read Timeout >>
    << IOT Write (EXO_STATUS_END: Code 10 - http:0) >>
    << [Exosite_Write] No Response >>
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    
    MEM HEAP
    avail: 32768
    used: 8908
    max: 13044
    err: 0
    exoHAL: << pcBuffer: Read Timeout >>
    << IOT Write (EXO_STATUS_END: Code 10 - http:0) >>
    << [Exosite_Write] No Response >>
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    >> Drop frame(NoMatchedPCB) RST->Sender <<
    

     

  • See how the heap grows every time we drop frames in above post. TCP timer interval and LWIP service timers have to be in somewhat near exact sync with the remote peer or frame drops randomly occur.

    Dropping frames in LWIP has a very bad outcome eventually leading to MPU faults - perhaps seconds, days or weeks of internet connection time. Message (>>NoMatchedPCB <<) is not an LWIP debug assert, rather an printf placed in the LWIP function that sends the remote host RST upon not receiving an http response even perhaps ACK from the remote peer.

    Repeating dropped frames drives the heap (used) count up and down, further upward with each new dropped frame. Application layer size and accumulative instruction times, interrupts and connection flags can prolong certain heap death by reducing or extending the time period in the LWIP TCP timer interval. Hence fewer dropped TCP frames keeps the heap used count low. Seems the best practice idea is to not drop any frames establishing the remote peer connection. That may be difficult to achieve based on local network traffic but in this case less drops is better.

    The entire LWIP timer context appears flawed in design to work well with the internet. A separate internal and dedicated timer might be more prudent in the LWIP design. Who cares if we sacrifice a dang peripheral timer if it keeps the TCP stack heap from corrupting. I rather like the idea LWIP internal timers have a direct relation to SYSCLK creating a true millisecond based on the divisor of the timer from the MCU clock rate. This case Systick/2000 or 16.6us (60kHz period) bumps the LWIP internal timer. That 60kHz may be equivalent to some exact fraction of a second but the IOT client application layer must be made synchronous to match. The example above the IOT client gets a slice of TCP stack every 26.56ms any more and it may over run the peer before RXD an ACK for the last frame sent or if ever ACK backs to client regardless of the http response.