Memory deallocation problem about lwesp HOT 19 CLOSED

In recent days, due to wrongly configured low-level communication, we saw some cases where memory was not reset properly. Netconn API has been updated, adding connection val_id in the netconn structure.

This also fixes potential invalid pointer accesses.

from lwesp.

Yes please - [email protected]

from lwesp.

I definitely use netconn API very often and was never able to run into memory allocation issues.

Can you show the code and how much have you allocated for memory?

from lwesp.

LWESP_MEM_SIZE is set to 0x4000, so around 16000 bytes. This error only occurs if the LWESP-memory is full and not (in my case) the FreeRTOS memory, am I right?

The netconn-API part is almost identical to the netconn_server-snippet, except that the sending of data is done by another thread.

That's the processsing thread for the respective TCP-connections:

/**
 * \brief           Thread to process single active connection
 * \param[in]       arg: Thread argument
 */
static void
netconn_server_processing_thread(void* const arg) {
    lwesp_netconn_p client;
    volatile lwesp_pbuf_p pbuf, p = NULL;
    volatile lwespr_t res;
    volatile uint8_t *data_pointer = NULL;

    //printf("Current heap size: %d \n", xPortGetFreeHeapSize());

    client = ((struct tcp_server_input_args*) arg)->client;
    current_client = client;
    if(current_client != NULL){
    	//printf("Overwriting older tcp client!! \n");
    }
    //printf("A new connection accepted!\r\n");   /* Print simple message */
    lwesp_netconn_set_receive_timeout(client, 0);

    do {

    	//osDelay(10);

    	res = lwesp_netconn_receive(client, &pbuf);

        if(res == lwespTIMEOUT){
            if(p != NULL){
    			lwesp_pbuf_free(p);
    			p = NULL;
            }
        	continue;
        }
        if (res == lwespOK) {

            if (p == NULL) {
                p = pbuf;    /* Set as first buffer */

            } else {
            	lwesp_pbuf_cat(p, pbuf);        /* Concatenate buffers together */
            }
            if(p != NULL){
            	tcpMsgHandler_handleReception(p,9,40);
    			lwesp_pbuf_free(p);
    			p = NULL;
            }
        }
    } while (res == lwespOK || res == lwespTIMEOUT);

    current_client = NULL;

    if (res != lwespCLOSED) {
    	lwesp_netconn_close(client);
    }     /* Close netconn connection */
    if (p != NULL) {                            /* Free received data */
        lwesp_pbuf_free(p);
        p = NULL;
    }


    //printf("Connection error: destroy TCP Thread! \n");
    lwesp_netconn_delete(client);                 /* Destroy client memory */
    lwesp_sys_thread_terminate(NULL);             /* Terminate this thread */
}

And that's the function called to send TCP data:

static bool tcpMsgHandler_transmitData( lwesp_netconn_p tcp_client,uint8_t* data, uint8_t len){

		volatile lwespr_t res = lwesp_netconn_write(tcp_client,(void*) data,len);
		if(res == lwespOK){
			res = lwesp_netconn_flush(tcp_client);
			return true;
		}
		else{
			//lwesp_mem_free_s((void**)&nc->buff.buff);
			//lwesp_mem_free_s(&pointer);
			printf("Error!\n");
		}
		return false;
}

The low-level code is the same as the stm32 template-code.

from lwesp.

Someone is allocating memory. If you have 16k, then few allocations of ~70bytes cannot lead to no memory.

from lwesp.

It's not a few allocations, that's just the end of the logs. The 76 bytes are allocated and freed every 80ms. And after ~2min the memory allocation error occurs.
For every new TCP reception/transmission and new socket connection is established.

from lwesp.

Can you debug all allocations and all frees in the system? Because from your MSG VAR messages, it is clear that any allocated pointer gets cleaned too.

from lwesp.

When I log the LWESP Memory, I suppose the threads are so busy with logging that the netconn server does not even get created and initialized. And when I set the LWESP_CFG_DBG_LVL_MIN to LWESP_DBG_LVL_WARNING then there are no logs at all.

Thats the start of the logging output:
Initializing LwESP
Library initialized!
[LWESP MEM] Callocation OK: 16 bytes, addr: 20012978
[LWESP MEM[LWESP MEM] Allocatio] Callocatn OK: 76 bion OK: 16 ytes, addrbytes, addr: 20012990: 200129E4

[LWESP MEM] Free size: 16, address: 20012978
[LWESP MEM] Callocation OK: 16 bytes, addr: 20012978
[LWESP MEM] Free size: 16, address: 200129E4
[LWESP MEM] Callocation OK: 16 bytes, addr: 200129E4
[LWESP MEM] Free size: 16, address: 20012978
[LWESP MEM] Callocation OK: 16 bytes, addr: 20012978
[LWESP MEM] Free size: 16, address: 200129E4
[LWESP MEM] Callocation OK: 16 bytes, addr: 200129E4
[LWESP MEM] Free size: 16, address: 20012978
[LWESP MEM] Callocation OK: 16 bytes, addr: 20012978
[LWESP MEM] Free size: 16, address: 200129E4
[LWESP MEM] Callocation OK: 16 bytes, addr: 200129E4
[LWESP MEM] Free size: 16, address: 20012978
[LWESP MEM] Callocation OK: 16 bytes, addr: 20012978
[LWESP MEM] Free size: 16, address: 200129E4
[LWESP MEM] Callocation OK: 16 bytes, addr: 200129E4
[LWESP MEM] Free size: 16, address: 20012978
[LWESP MEM] Callocation OK: 16 bytes, addr: 20012978
[LWESP MEM] Free size: 16, address: 200129E4
[LWESP MEM] Callocation OK: 16 bytes, addr: 200129E4
[LWESP MEM] Free size: 16, address: 20012978
[LWESP MEM] Callocation OK: 16 bytes, addr: 20012978
[LWESP MEM] Free size: 16, address: 200129E4
[LWESP MEM] Callocation OK: 16 bytes, addr: 200129E4
[LWESP MEM] Free size: 16, address: 20012978
[LWESP MEM] Callocation OK: 16 bytes, addr: 20012978
[LWESP MEM] Free size: 16, address: 200129E4
[LWESP MEM] Callocation OK: 16 bytes, addr: 200129E4
[LWESP MEM] Free size: 16, address: 20012978
[LWESP MEM] Callocation OK: 16 bytes, addr: 20012978
[LWESP MEM] Free size: 16, address: 200129E4
[LWESP MEM] Callocation OK: 16 bytes, addr: 200129E4
[LWESP MEM] Free size: 16, address: 20012978
.
.
.

Is it normal that the lib communicates with the ESP that often during initialization?

from lwesp.

Yes, there are many commands that are sent out to device during the startup. 16 bytes allocation seems to be from lwesp_timeout_add function call, where structure is 16 bytes on 32-bit systems.

See this:

[LWESP MEM[LWESP MEM] Allocatio] Callocatn OK: 76 bion OK: 16 ytes, addrbytes, addr: 20012990: 200129E4

This is not normal. Do you have some mutex issues or UART overflow problems?

from lwesp.

Yes, you are right. Because at the UART for the debugging messages only the _putchar method itself is thread-safe, so if two threads want to write at the same time, that happens.
But other than for readability reasons, is there a problem with that?

from lwesp.

Thanks for your help ! :)
Do you know which part of the low level communication part could be misconfigured?
I used exactly the same configuration as in the lwesp_ll_stm32f429zi_nucleo.c-file.

I updated the lwesp-code with the new commits, but nothing changed. That's the end of the logs:
After that the lwesp system-memory is full.
.
.
.
[LWESP NETCONN] Received pbuf contains 49 bytes. Handle written to receive mbox
[LWESP NETCONN] netcon_receive: Got pbuf object handle at 0x20016890. Len/Tot_len: 49/49
[LWESP NETCONN] netcon_receive: Got object handle for close event
[LWESP IPD] New length to read: 48 bytes
[LWESP IPD] Bytes read: 48
[LWESP NETCONN] Received pbuf contains 49 bytes. Handle written to receive mbox
[LWESP NETCONN] netcon_receive: Got pbuf object handle at 0x200168A8. Len/Tot_len: 49/49
[LWESP NETCONN] netcon_receive: Got object handle for close event
[LWESP IPD] New length to read: 48 bytes
[LWESP IPD] Bytes read: 48
[LWESP NETCONN] Received pbuf contains 49 bytes. Handle written to receive mbox
[LWESP NETCONN] netcon_receive: Got pbuf object handle at 0x20016854. Len/Tot_len: 49/49
[LWESP NETCONN] netcon_receive: Got object handle for close event
[LWESP IPD] New length to read: 48 bytes
[LWESP IPD] Bytes read: 48
[LWESP NETCONN] Received pbuf contains 49 bytes. Handle written to receive mbox
[LWESP NETCONN] netcon_receive: Got pbuf object handle at 0x2001686C. Len/Tot_len: 49/49
[LWESP NETCONN] netcon_receive: Got object handle for close event
[LWESP IPD] New length to read: 48 bytes
[LWESP IPD] Bytes read: 48
[LWESP NETCONN] Received pbuf contains 49 bytes. Handle written to receive mbox
[LWESP NETCONN] netcon_receive: Got pbuf object handle at 0x200168F0. Len/Tot_len: 49/49
[LWESP NETCONN] netcon_receive: Got object handle for close event
[LWESP IPD] New length to read: 48 bytes
[LWESP IPD] Bytes read: 48
[LWESP NETCONN] Received pbuf contains 49 bytes. Handle written to receive mbox
[LWESP NETCONN] netcon_receive: Got pbuf object handle at 0x20016908. Len/Tot_len: 49/49
[LWESP NETCONN] netcon_receive: Got object handle for close event
[LWESP IPD] New length to read: 23 bytes
[LWESP IPD] Bytes read: 23
[LWESP NETCONN] Received pbuf contains 24 bytes. Handle written to receive mbox
[LWESP NETCONN] netcon_receive: Got pbuf object handle at 0x20016848. Len/Tot_len: 24/24

Communication seems to be more unstable in general, with occasional sending/receiving times of up to 1-2sec.

from lwesp.

Can you give me a hint which part of the low-level communication is misconfigured?
With the latest versions (with "lwesp_pub_s()") the memory allocation error still occurs - always at the same time and with the same number of bytes with my test program. So at least the behavior of the bug is deterministic.

from lwesp.

OK understood - I see you have F429, so maybe there is no issue on Low-Level part, as you have no cache in the product.
You said you are sending and receiving data from different threads, correct? What happens if you do everything in one thread?

from lwesp.

Yes, a STM32F407 to be precise :)
Interestingly, it behaves even more unstable with only one thread. The send/receive time has a higher variance and the same error occurs after a certain amount of time.
But I had almost the same software running quite stable with another application also with only one thread (with ESP-AT V2.1.0 and lwesp-v1.0.0) about 2 years ago.

Could it have something to do with the lwesp options? Or are there any debugging/logging options that could give a hint which memory was allocated but not freed anymore?

from lwesp.

If you enable PBUF, MEM and MSG events, you may find a lot.

I'd be curious to have a debug session with yo, actually...I am not able to reproduce the issue you are facing, actually.

from lwesp.

Sure!

With the exception of MEM (which stalls the program flow because of its massive amount of debug msgs), I have logged extensively with PBUF and MSG, but could not find any hints of any memory leaks.

from lwesp.

So I got the debug logs to work with the MEM events as well. Those are part of the logs:
Do you notice any unusual behavior during allocation/deallocation within these logs?
.
.
.
[LWESP MEM] Free size: 2048 bytes, addr: 2001329C
[LWESP MEM] Callocation OK: 52 bytes, addr: 200129C4
[LWESP MEM] Callocation OK: 16 bytes, addr: 20013230
[LWESP MEM] Allocation OK: 76 bytes, addr: 2001329C
[LWESP MEM] Callocation OK: 16 bytes, addr: 20013248
[LWESP MEM] Free size: 16 bytes, addr: 20013284
[LWESP MEM] Allocation OK: 76 bytes, addr: 200132F0
[LWESP MEM] Free size: 76 bytes, addr: 2001329C
[LWESP MEM] Allocation OK: 77 bytes, addr: 20013260
[LWESP MEM] Free size: 80 bytes, addr: 20013260
[LWESP MEM] Allocation OK: 2048 bytes, addr: 20013344
[LWESP MEM] Allocation OK: 76 bytes, addr: 20013260
[LWESP MEM] Free size: 76 bytes, addr: 200132F0
[LWESP MEM] Free size: 52 bytes, addr: 200129C4
[LWESP MEM] Free size: 76 bytes, addr: 20013260
[LWESP MEM] Free size: 2048 bytes, addr: 20013344
[LWESP MEM] Callocation OK: 52 bytes, addr: 200129C4
[LWESP MEM] Callocation OK: 16 bytes, addr: 20013260
[LWESP MEM] Allocation OK: 76 bytes, addr: 20013278
[LWESP MEM] Allocation OK: 76 bytes, addr: 200132CC
[LWESP MEM] Callocation OK: 16 bytes, addr: 20013320
[LWESP MEM] Free size: 16 bytes, addr: 20013248
[LWESP MEM] Callocation OK: 16 bytes, addr: 20013248
[LWESP MEM] Free size: 16 bytes, addr: 20013320
[LWESP MEM] Callocation OK: 16 bytes, addr: 20013320
[LWESP MEM] Free size: 16 bytes, addr: 20013248
[LWESP MEM] Callocation OK: 16 bytes, addr: 20013248
[LWESP MEM] Free size: 16 bytes, addr: 20013320
[LWESP MEM] Free size: 76 bytes, addr: 20013278
[LWESP MEM] Allocation OK: 77 bytes, addr: 20013320
[LWESP MEM] Free size: 80 bytes, addr: 20013320
[LWESP MEM] Allocation OK: 2048 bytes, addr: 20013320
[LWESP MEM] Allocation OK: 76 bytes, addr: 20013278
[LWESP MEM] Free size: 76 bytes, addr: 200132CC
[LWESP MEM] Free size: 52 bytes, addr: 200129C4
[LWESP MEM] Free size: 76 bytes, addr: 20013278
[LWESP MEM] Free size: 2048 bytes, addr: 20013320
[LWESP MEM] Callocation OK: 52 bytes, addr: 200129C4
[LWESP MEM] Callocation OK: 16 bytes, addr: 20013278
[LWESP MEM] Allocation OK: 76 bytes, addr: 20013290
[LWESP MEM] Callocation OK: 16 bytes, addr: 200132E4
[LWESP MEM] Free size: 16 bytes, addr: 20013248
[LWESP MEM] Allocation OK: 76 bytes, addr: 200132FC
[LWESP MEM] Free size: 76 bytes, addr: 20013290
[LWESP MEM] Allocation OK: 77 bytes, addr: 20013350
[LWESP MEM] Free size: 80 bytes, addr: 20013350
[LWESP MEM] Allocation OK: 2048 bytes, addr: 20013350
[LWESP MEM] Allocation OK: 76 bytes, addr: 20013290
[LWESP MEM] Free size: 76 bytes, addr: 200132FC
[LWESP MEM] Free size: 76 bytes, addr: 20013290
[LWESP MEM] Free size: 2048 bytes, addr: 20013350
[LWESP MEM] Free size: 52 bytes, addr: 200129C4
[LWESP MEM] Callocation OK: 52 bytes, addr: 200129C4
[LWESP MEM] Callocation OK: 16 bytes, addr: 20013248
.
.
.
I don't really understand why sometimes 80 bytes are freed when there were never exactly 80 bytes allocated.

from lwesp.

I don't really understand why sometimes 80 bytes are freed when there were never exactly 80 bytes allocated.

This is because I am printing the user input data size len (77 bytes) while when free is called, debug prints actual size of allocation, which was 80bytes. Reason is that library uses memory alignment, by default set to4` bytes.

It would be better to update the library to print actual allocation to not confuse you. Updated just now with latest commit.

What I see clearly is that 2048 blocks are allocated and freed afterwards and you are still entering the memory failure?
Do you have some custom lwesp_timeout feature?

We will need a computer debugging. I'm not able to see an issue from this.

from lwesp.

No, I only use the standard lwesp functions.
Sure, that would be great :)
Should I contact you by email regarding the debugging session?

from lwesp.