Possible memory leak in tlsio_esp_tls.c (CA-64)
Opened this issue · 14 comments
Hi,
I'm currently working on the ESP32 that pushes collected data to the Azure IoThub. I started from the iothub_client_sample_mqtt and modified it to my specific needs. I added a parameter to the iothub_client_sample_mqtt_run() function for my data and I send my data only once to the Azure IoTHub. After +- 40 succeeded commits. I get an "esp-tls: mbedtls_ssl_handshake returned -0x4c" which indicates that there is a heap problem.
I used the proposed heap memory debug (https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/system/heap_debug.html) from Espressif. Where is start tracing the heap before calling the iothub_client_sample_mqtt_run() funcion and stop the tracing after the funcion.
my output tells me among other things the following:
1784 bytes (@ 0x3ffec820) allocated CPU 1 ccount 0xcdfcfd48 caller 0x400d9b88:0x400e5e87
0x400d9b88: tlsio_esp_tls_create at /home/mathias/esp/esp-azure/port/src/tlsio_esp_tls.c:218
which indicates that there is an memory leak in tlsio_esp_tls.c
Any solutions?
Hello,
I tested the iothub_client_sample_mqtt if the error occurs here as well. I added a for loop in the azure_task and added heap tracing.
for(int i =0; i<=200; i++){
ESP_ERROR_CHECK( heap_trace_start(HEAP_TRACE_LEAKS) );
iothub_client_sample_mqtt_run();
ESP_ERROR_CHECK( heap_trace_stop() );
heap_trace_dump();
ESP_LOGI(TAG, "free Heap size(if): %x", xPortGetFreeHeapSize() );
i++;
}
if i run this my output is as followed
Initializing SNTP
ESP platform sntp inited!
I (185933) platform: The current date/time is: Tue Jun 16 09:05:00 2020
IoTHubClient_LL_SetMessageCallback...successful.
IoTHubClient_LL_SendEventAsync accepted message [0] for transmission to IoT Hub.
-> 09:05:01 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: Test2703.azure-devices.net/1/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.14%20(native%3b%20freertos%3b%20esp%20platform) | PWD: XXXX | CLEAN: 0
<- 09:05:01 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
Connection Status result:IOTHUB_CLIENT_CONNECTION_AUTHENTICATED, Connection Status reason: IOTHUB_CLIENT_CONNECTION_OK
-> 09:05:01 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/1/messages/devicebound/# | QOS: 1
-> 09:05:01 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/1/messages/events/temperatureAlert=false | PACKET_ID: 3 | PAYLOAD_LEN: 83
<- 09:05:01 SUBACK | PACKET_ID: 2 | RETURN_CODE: 1
<- 09:05:01 PUBACK | PACKET_ID: 3
Confirmation[0] received for message tracking id = 0 with result = IOTHUB_CLIENT_CONFIRMATION_OK
exit
iothub_client_sample_mqtt has gotten quit message, call DoWork 3 more time to complete final sending...
-> 09:05:01 DISCONNECT
10 allocations trace (100 entry buffer)
1784 bytes (@ 0x3fff14f4) allocated CPU 0 ccount 0xecdfc9dc caller 0x400d7ff0:0x400e42ab
0x400d7ff0: tlsio_esp_tls_create at /home/mathias/esp/esp-azure/port/src/tlsio_esp_tls.c:218
0x400e42ab: xio_create at /home/mathias/esp/esp-azure/azure-iot-sdk-c/c-utility/src/xio.c:47
208 bytes (@ 0x3ffcc7d8) allocated CPU 0 ccount 0xecfc7780 caller 0x400ff547:0x400ff5ba
0x400ff547: mem_malloc at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400ff5ba: do_memp_malloc_pool at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/memp.c:254
16 bytes (@ 0x3ffbc438) allocated CPU 0 ccount 0xfd1fd1a8 caller 0x400ff547:0x400ff5ba
0x400ff547: mem_malloc at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400ff5ba: do_memp_malloc_pool at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/memp.c:254
16 bytes (@ 0x3ffbd118) allocated CPU 0 ccount 0xfd201e14 caller 0x400ff547:0x400ff5ba
0x400ff547: mem_malloc at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400ff5ba: do_memp_malloc_pool at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/memp.c:254
16 bytes (@ 0x3ffbd12c) allocated CPU 0 ccount 0xfd2067d8 caller 0x400ff547:0x400ff5ba
0x400ff547: mem_malloc at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400ff5ba: do_memp_malloc_pool at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/memp.c:254
16 bytes (@ 0x3ffbc5c4) allocated CPU 0 ccount 0xfd20bc58 caller 0x400ff547:0x400ff5ba
0x400ff547: mem_malloc at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400ff5ba: do_memp_malloc_pool at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/memp.c:254
16 bytes (@ 0x3ffbc874) allocated CPU 0 ccount 0xfd212828 caller 0x400ff547:0x400ff5ba
0x400ff547: mem_malloc at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400ff5ba: do_memp_malloc_pool at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/memp.c:254
16 bytes (@ 0x3ffbd140) allocated CPU 0 ccount 0xfd2171d4 caller 0x400ff547:0x400ff5ba
0x400ff547: mem_malloc at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400ff5ba: do_memp_malloc_pool at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/memp.c:254
16 bytes (@ 0x3ffbcd70) allocated CPU 0 ccount 0xfd21b428 caller 0x400ff547:0x400ff5ba
0x400ff547: mem_malloc at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400ff5ba: do_memp_malloc_pool at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/memp.c:254
16 bytes (@ 0x3ffbbeb8) allocated CPU 0 ccount 0xfd9c644c caller 0x400ff547:0x400ff5ba
0x400ff547: mem_malloc at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400ff5ba: do_memp_malloc_pool at /home/mathias/esp/esp-idf/components/lwip/lwip/src/core/memp.c:254
2120 bytes 'leaked' in trace (10 allocations)
total allocations 388 total frees 16729
I (187963) azure: free Heap size(if): fb18
After running this a wile the following appears in the terminal:
Initializing SNTP
ESP platform sntp inited!
I (190113) platform: The current date/time is: Tue Jun 16 09:05:04 2020
IoTHubClient_LL_SetMessageCallback...successful.
IoTHubClient_LL_SendEventAsync accepted message [0] for transmission to IoT Hub.
E (191473) esp-tls: mbedtls_ssl_handshake returned -0x10
I (191473) esp-tls: Certificate verified.
Any fix for the heap leak?
I gonna close this issue due to interest.
@MathiasCraeghs we have update azure-iot-c-sdk to the latest LTS_06_2020_Ref01 today. Can you try with that and see? Since the azure sdk itself has had many fixes, this will help understand if the issue is/was in the azure code, or the espressif port.
I updated to the newest version and the leak is still there. I also suspect that it is this file. @MathiasCraeghs can you reopen the issue? Or did you find a fix?
I didn't find a fix, now I just reboot the ESP after x amount off calls
I am unable to reproduce this issue. Following are environment details, using latest esp-azure:
$ cd esp-azure
$ git log --oneline
b67efd7 Merge branch 'bugfix/prov_docs' into 'master'
$ git submodule
989f1dc66c7de53cb14d29eb051003eec0de798e azure-iot-sdk-c (2018-03-07-temp-pod-876-g989f1dc66)
Patch used is per below:
diff --git examples/iothub_client_sample_mqtt/main/azure_main.c examples/iothub_client_sample_mqtt/main/azure_main.c
index 1097d30..48f06c9 100644
--- examples/iothub_client_sample_mqtt/main/azure_main.c
+++ examples/iothub_client_sample_mqtt/main/azure_main.c
@@ -76,14 +76,27 @@ static void initialise_wifi(void)
ESP_ERROR_CHECK( esp_wifi_start() );
}
+#include "esp_heap_trace.h"
void azure_task(void *pvParameter)
{
xEventGroupWaitBits(wifi_event_group, CONNECTED_BIT,
false, true, portMAX_DELAY);
ESP_LOGI(TAG, "Connected to AP success!");
- iothub_client_sample_mqtt_run();
-
+ #define NUM_RECORDS 1000
+ static heap_trace_record_t trace_record[NUM_RECORDS];
+ heap_trace_init_standalone(trace_record, NUM_RECORDS);
+
+ for (int i = 0; i < 100; i++) {
+ printf("BEGIN: Free Heap: %d, Min. Free Heap: %d\n", esp_get_free_heap_size(), esp_get_minimum_free_heap_size());
+ ESP_ERROR_CHECK( heap_trace_start(HEAP_TRACE_LEAKS) );
+ iothub_client_sample_mqtt_run();
+ vTaskDelay(200);
+ ESP_ERROR_CHECK( heap_trace_stop() );
+ heap_trace_dump();
+ printf("END: Free Heap: %d, Min. Free Heap: %d\n", esp_get_free_heap_size(), esp_get_minimum_free_heap_size());
+ }
+
vTaskDelete(NULL);
}
Heap backtrace is per below:
<- 06:32:18 PUBACK | PACKET_ID: 7
Confirmation[4] received for message tracking id = 4 with result = IOTHUB_CLIENT_CONFIRMATION_OK
exit
iothub_client_sample_mqtt has gotten quit message, call DoWork 3 more time to complete final sending...
-> 06:32:18 DISCONNECT
9 allocations trace (1000 entry buffer)
208 bytes (@ 0x3ffc79d4) allocated CPU 0 ccount 0xaada59c0 caller 0x400f2260:0x400f22d6:0x400f2347:0x400f4da7
0x400f2260: mem_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400f22d6: do_memp_malloc_pool at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:254
0x400f2347: memp_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:350 (discriminator 2)
0x400f4da7: tcp_alloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/tcp.c:1920
16 bytes (@ 0x3ffc57c0) allocated CPU 0 ccount 0xf5e0f370 caller 0x400f2260:0x400f22d6:0x400f2347:0x400f8c8c
0x400f2260: mem_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400f22d6: do_memp_malloc_pool at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:254
0x400f2347: memp_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:350 (discriminator 2)
0x400f8c8c: sys_timeout_abs at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/timeouts.c:199
16 bytes (@ 0x3ffc9c3c) allocated CPU 0 ccount 0xf5e72c58 caller 0x400f2260:0x400f22d6:0x400f2347:0x400f8c8c
0x400f2260: mem_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400f22d6: do_memp_malloc_pool at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:254
0x400f2347: memp_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:350 (discriminator 2)
0x400f8c8c: sys_timeout_abs at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/timeouts.c:199
16 bytes (@ 0x3ffd9250) allocated CPU 0 ccount 0xf5ed5760 caller 0x400f2260:0x400f22d6:0x400f2347:0x400f8c8c
0x400f2260: mem_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400f22d6: do_memp_malloc_pool at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:254
0x400f2347: memp_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:350 (discriminator 2)
0x400f8c8c: sys_timeout_abs at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/timeouts.c:199
16 bytes (@ 0x3ffdeef0) allocated CPU 0 ccount 0xf5f398b8 caller 0x400f2260:0x400f22d6:0x400f2347:0x400f8c8c
0x400f2260: mem_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400f22d6: do_memp_malloc_pool at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:254
0x400f2347: memp_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:350 (discriminator 2)
0x400f8c8c: sys_timeout_abs at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/timeouts.c:199
16 bytes (@ 0x3ffc5b8c) allocated CPU 0 ccount 0xf5f9e380 caller 0x400f2260:0x400f22d6:0x400f2347:0x400f8c8c
0x400f2260: mem_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400f22d6: do_memp_malloc_pool at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:254
0x400f2347: memp_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:350 (discriminator 2)
0x400f8c8c: sys_timeout_abs at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/timeouts.c:199
16 bytes (@ 0x3ffc5ba0) allocated CPU 0 ccount 0xf60010b4 caller 0x400f2260:0x400f22d6:0x400f2347:0x400f8c8c
0x400f2260: mem_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400f22d6: do_memp_malloc_pool at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:254
0x400f2347: memp_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:350 (discriminator 2)
0x400f8c8c: sys_timeout_abs at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/timeouts.c:199
16 bytes (@ 0x3ffc9c64) allocated CPU 0 ccount 0xfaa5946c caller 0x400f2260:0x400f22d6:0x400f2347:0x400f8c8c
0x400f2260: mem_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400f22d6: do_memp_malloc_pool at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:254
0x400f2347: memp_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:350 (discriminator 2)
0x400f8c8c: sys_timeout_abs at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/timeouts.c:199
16 bytes (@ 0x3ffc9cc8) allocated CPU 1 ccount 0xf8a27e24 caller 0x400f2260:0x400f22d6:0x400f2347:0x400f8c8c
0x400f2260: mem_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/mem.c:237
0x400f22d6: do_memp_malloc_pool at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:254
0x400f2347: memp_malloc at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/memp.c:350 (discriminator 2)
0x400f8c8c: sys_timeout_abs at /home/mjain/work/vanilla/esp-idf/components/lwip/lwip/src/core/timeouts.c:199
336 bytes 'leaked' in trace (9 allocations)
total allocations 913 total frees 15290
END: Free Heap: 156656, Min. Free Heap: 83676
BEGIN: Free Heap: 156656, Min. Free Heap: 83676
Please note that, even though heap tracing shows some memory leak, its mostly coming from networking stack and that too from its timers, which should get freed if we increase delay before stopping heap trace.
Can you please confirm above findings on your side? Please provide your sdkconfig if you still see memory leak w.r.t TLS connection.
As I posted in this issue, the number of leaked bytes is quite low for me as well (~100 bytes per callback call). Can you explain a little bit more what you mean with the timers and setting a delay?
@jubueche Probably we are discussing 2 different issues here. This issue highlights that there is leak of 1784 across Azure TLS connection, which I was unable to reproduce. Regarding timers, what I meant was, once you close TLS connection it may not free up entire memory associated with corresponding TCP socket, graceful shutdown (and TCP TIME_WAIT state) may keep some memory (in the form of networking timers etc.) for certain duration.
Regarding your issue of memory leak across callback, did you check heap backtrace?
Closing due to lack of followup. Please feel free to open if there are any updates.
Note: Please note that there was one issue in heap tracing (IDF v4.1 onwards) resulting in random crash, more details and fix pointer at espressif/esp-idf#5758. Recommend to have that fix available while enabling heap tracing.
@MathiasCraeghs I have exactly the same issue
@mahavirj Thanks for pointing to espressif/esp-idf#5758 I was able to do heap tracing with your help. Can you please confirm that you used trusted certificate X509 for your test?
In my case I can create this heap loss in tlsio_esp_tls.c:218 without sending a single packet. In my loop the azure is initialised with X509 certs, wait for about 10 seconds, then azure is destroyed, wait for it to return and then after a few seconds do a heap dump.
Over a period of time the heap remaining is being reduced by 1900 bytes every init and destroy cycle and then device runs out of memory which causes reboot.
Mathias has it like this:
1784 bytes (@ 0x3fff14f4) allocated CPU 0 ccount 0xecdfc9dc caller 0x400d7ff0:0x400e42ab
0x400d7ff0: tlsio_esp_tls_create at /home/mathias/esp/esp-azure/port/src/tlsio_esp_tls.c:218
Mine is like this.
1880 bytes (@ 0x3ffc8778) allocated CPU 0 ccount 0x7f184cec caller 0x400e3318:0x400ef637
0x400e3318: tlsio_esp_tls_create at /project/build/../components/azure-esp-sdk/port/src/tlsio_esp_tls.c:218
@mahavirj I'll appreciate if you can reopen this issue
@teekaytk Can you please increase stack depth in heap tracing and see from where these allocations are coming? Also please post your sample code as well.
@mahavirj
Thanks for re-opening the ticket
We are using MQTT protocol
Please find the log attached , I increased the stack depth to 10 maximum allowed
leak1.log
Also see code below
it is basically these two functions called one after the other, one to init the azure and second to destroy it
int azure_init(void)
{
IOTHUB_CLIENT_TRANSPORT_PROVIDER protocol;
// Select the Protocol to use with the connection
#ifdef SAMPLE_MQTT
protocol = MQTT_Protocol;
#endif // SAMPLE_MQTT
#ifdef SAMPLE_MQTT_OVER_WEBSOCKETS
protocol = MQTT_WebSocket_Protocol;
#endif // SAMPLE_MQTT_OVER_WEBSOCKETS
#ifdef SAMPLE_AMQP
protocol = AMQP_Protocol;
#endif // SAMPLE_AMQP
#ifdef SAMPLE_AMQP_OVER_WEBSOCKETS
protocol = AMQP_Protocol_over_WebSocketsTls;
#endif // SAMPLE_AMQP_OVER_WEBSOCKETS
#ifdef SAMPLE_HTTP
protocol = HTTP_Protocol;
#endif // SAMPLE_HTTP
//! Soft init for this module
// Init the message queue
if(strcmp(connectionString, "") == 0)
{
ESP_LOGE(TAG, "NO IoT String\r\n");
}
else
{
if(strcmp(x509_cert_str, "") == 0)
{
ESP_LOGE(TAG, "NO Cert\r\n");
}
else
{
if(strcmp(private_key_str, "") == 0)
{
ESP_LOGE(TAG, "NO Key\r\n");
}
else
{
if(platform_init() != 0)
{
ESP_LOGE(TAG, "Failed to initialize the platform.\r\n");
}
else
{
if((iotHubClientHandle = IoTHubDeviceClient_LL_CreateFromConnectionString(connectionString, protocol)) == NULL)
{
ESP_LOGE(TAG, "iotHubClientHandle is NULL!\r\n");
}
else
{
// Uncomment the following lines to enable verbose logging (e.g., for debugging).
bool traceOn = true;
(void)IoTHubDeviceClient_LL_SetOption(iotHubClientHandle, OPTION_LOG_TRACE, &traceOn);
IoTHubDeviceClient_LL_SetConnectionStatusCallback(iotHubClientHandle, connection_status_callback, NULL);
// Setting the Trusted Certificate. This is only necessary on system with without
// built in certificate stores.
//#ifdef SET_TRUSTED_CERT_IN_SAMPLES
// For mbed add the certificate information
if(IoTHubDeviceClient_LL_SetOption(iotHubClientHandle, "TrustedCerts", certificates) != IOTHUB_CLIENT_OK)
{
ESP_LOGE(TAG, "failure to set option \"TrustedCerts\"\r\n");
}
//#endif // SET_TRUSTED_CERT_IN_SAMPLES
// Set the X509 certificates in the SDK
if((IoTHubDeviceClient_LL_SetOption(iotHubClientHandle, OPTION_X509_CERT, x509_cert_str) != IOTHUB_CLIENT_OK) ||
(IoTHubDeviceClient_LL_SetOption(iotHubClientHandle, OPTION_X509_PRIVATE_KEY, private_key_str) != IOTHUB_CLIENT_OK))
{
printf("failure to set options for x509, aborting\r\n");
}
/* Setting Message call back, so we can receive Commands. */
else if(IoTHubDeviceClient_LL_SetMessageCallback(iotHubClientHandle, ReceiveMessageCallback, &receiveContext) != IOTHUB_CLIENT_OK)
{
ESP_LOGE(TAG, "IoTHubDeviceClient_LL_SetMessageCallback... FAILED!");
}
else
{
return ESP_OK;
}
IoTHubDeviceClient_LL_Destroy(iotHubClientHandle);
}
platform_deinit();
}
}
}
}
return ESP_FAIL;
}
static void quit_azure(void)
{
IoTHubDeviceClient_LL_Destroy(iotHubClientHandle);
platform_deinit();
}
}
@teekaytk We have update the azure-iot-sdk-c to LTS_07_2020_Ref02, can you check out again?
Thanks it is tested and issue is resolved on the new update. You may close the ticket please.