Esp-idf: Memory (heap) out after +100 TLS request with custom x509 root certificate (IDFGH-2950)

Created on 24 Mar 2020 · 12Comments · Source: espressif/esp-idf

What to do to produce the error:

Use ESP-IDF Example https_mbedtls
Get root certificate of your server (self signed in my case) by using OpenSSL command: openssl s_client -showcerts -servername *.mydomain.com -connect MyServerIP:443 </dev/null 2>/dev/null|openssl x509 -outform PEM >/home/me/Desktop/server_root_cert.pem
In menuconfig add custom certificate to the custom bundle CONFIG_MBEDTLS_CUSTOM_CERTIFICATE_BUNDLE_PATH="/home/me/Desktop/server_root_cert.pem"
Build the firmware and flash..

It's will work great, but on every request mbedTLS allocate around ~2000 bytes on handshake stage, so after around ~120 requests we get a out of memory warning.

Note: _I get free heap size by using_ ESP_LOGW(TAG, "Free Heap: %d", esp_get_free_heap_size());

Monitor log

--- idf_monitor on /dev/ttyUSB1 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:4
load:0x3fff0034,len:7224
load:0x40078000,len:13092
load:0x40080400,len:3936
0x40080400: _init at ??:?

entry 0x40080688
I (28) boot: ESP-IDF v4.2-dev-701-g0ae960f2f-dirty 2nd stage bootloader
I (29) boot: compile time 15:53:08
I (30) boot: chip revision: 1
I (33) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (40) boot.esp32: SPI Speed      : 40MHz
I (45) boot.esp32: SPI Mode       : DIO
I (50) boot.esp32: SPI Flash Size : 2MB
I (54) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (63) boot: ## Label            Usage          Type ST Offset   Length
I (70) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (78) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (85) boot:  2 factory          factory app      00 00 00010000 00100000
I (93) boot: End of partition table
I (97) boot_comm: chip revision: 1, min. application chip revision: 0
I (104) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x2e1c4 (188868) map
I (185) esp_image: segment 1: paddr=0x0003e1ec vaddr=0x3ffb0000 size=0x01e2c (  7724) load
I (189) esp_image: segment 2: paddr=0x00040020 vaddr=0x400d0020 size=0x85194 (545172) map
0x400d0020: _stext at ??:?

I (399) esp_image: segment 3: paddr=0x000c51bc vaddr=0x3ffb1e2c size=0x01b18 (  6936) load
I (402) esp_image: segment 4: paddr=0x000c6cdc vaddr=0x40080000 size=0x00404 (  1028) load
0x40080000: _WindowOverflow4 at /home/me/Desktop/MY_FIRMWARE/SDK/ESP_IDF/components/freertos/xtensa/xtensa_vectors.S:1817

I (406) esp_image: segment 5: paddr=0x000c70e8 vaddr=0x40080404 size=0x14be4 ( 84964) load
I (463) boot: Loaded app from partition at offset 0x10000
I (463) boot: Disabling RNG early entropy source...
I (464) cpu_start: Pro cpu up.
I (467) cpu_start: Application information:
I (472) cpu_start: Project name:     https-mbedtls
I (478) cpu_start: App version:      1
I (482) cpu_start: Compile time:     Mar 23 2020 15:52:59
I (488) cpu_start: ELF file SHA256:  3e4cef9cc8901077...
I (494) cpu_start: ESP-IDF:          v4.2-dev-701-g0ae960f2f-dirty
I (501) cpu_start: Starting app cpu, entry point is 0x40081280
0x40081280: call_start_cpu1 at /home/me/Desktop/MY_FIRMWARE/SDK/ESP_IDF/components/esp32/cpu_start.c:273

I (0) cpu_start: App cpu up.
I (511) heap_init: Initializing. RAM available for dynamic allocation:
I (518) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (524) heap_init: At 3FFB9530 len 00026AD0 (154 KiB): DRAM
I (531) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (537) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (543) heap_init: At 40094FE8 len 0000B018 (44 KiB): IRAM
I (550) cpu_start: Pro cpu start user code
I (568) spi_flash: detected chip: generic
I (569) spi_flash: flash io: dio
W (569) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.                                                                                                                
I (579) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (685) wifi:wifi driver task: 3ffc0e0c, prio:23, stack:3584, core=0
I (685) system_api: Base MAC address is not set
I (685) system_api: read default base MAC address from EFUSE
I (705) wifi:wifi firmware version: d76a2dd
I (705) wifi:config NVS flash: enabled
I (705) wifi:config nano formating: disabled
I (705) wifi:Init dynamic tx buffer num: 32
I (715) wifi:Init data frame dynamic rx buffer num: 32
I (715) wifi:Init management frame dynamic rx buffer num: 32
I (725) wifi:Init management short buffer num: 32
I (725) wifi:Init static rx buffer size: 1600
I (735) wifi:Init static rx buffer num: 10
I (735) wifi:Init dynamic rx buffer num: 32
I (745) example_connect: Connecting to my_wireless...
I (835) phy: phy_version: 4180, cb3948e, Sep 12 2019, 16:39:13, 0, 0
I (835) wifi:mode : sta (c4:4f:33:3e:c1:c5)
I (845) example_connect: Waiting for IP
I (965) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (965) wifi:state: init -> auth (b0)
I (965) wifi:state: auth -> assoc (0)
I (975) wifi:state: assoc -> run (10)
I (1005) wifi:connected with my_wireless, aid = 23, channel 1, BW20, bssid = b4:fb:e4:e5:41:c0
I (1005) wifi:security type: 3, phy: bgn, rssi: -65
I (1005) wifi:pm start, type: 1

I (1045) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (1675) esp_netif_handlers: sta ip: 192.168.165.191, mask: 255.255.255.0, gw: 192.168.165.1
I (1675) example_connect: Got IP event!
I (2675) example_connect: Got IPv6 event!
I (2675) example_connect: Connected to my_wireless
I (2675) example_connect: IPv4 address: 192.168.165.191
I (2675) example_connect: IPv6 address: fe80:0000:0000:0000:c64f:33ff:fe3e:xxxx
I (2685) example: Seeding the random number generator
I (2695) example: Attaching the certificate bundle...
I (2695) example: Setting hostname for TLS session...
I (2705) example: Setting up the SSL/TLS structure...
W (2715) example: Free Heap: 206168 <<----------------------------------------
I (2715) example: Connecting to 192.168.168.XX:443...
I (2735) example: Connected.
I (2735) example: Performing the SSL/TLS handshake...
I (2845) esp-x509-crt-bundle: Certificate validated
I (3795) example: Verifying peer X.509 certificate...
I (3795) example: Certificate verified.
I (3795) example: Cipher suite is TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384
I (3805) example: Writing HTTP request...
I (3815) example: 103 bytes written
I (3815) example: Reading HTTP response...
HTTP/1.1 200 OK
Date: Tue, 24 Mar 2020 12:04:51 GMT
Server: Apache/2.4.37 (centos) OpenSSL/1.1.1c mod_fcgid/2.3.9
Last-Modified: Thu, 12 Mar 2020 18:08:25 GMT
ETag: "15-xxxx"
Accept-Ranges: bytes
Content-Length: 21
Connection: close
Content-Type: text/html; charset=UTF-8

<html>...</html>

I (3855) example: Completed 1 requests
I (3855) example: 10...
...
I (13855) example: 0...
I (14855) example: Starting again!
W (14855) example: Free Heap: 204212 <<----------------------------------------
I (14855) example: Connecting to 192.168.168.XX:443...
I (14865) example: Connected.
I (14865) example: Performing the SSL/TLS handshake...
I (14985) esp-x509-crt-bundle: Certificate validated
I (15935) example: Verifying peer X.509 certificate...
I (15935) example: Certificate verified.
I (15935) example: Cipher suite is TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384
I (15945) example: Writing HTTP request...
I (15955) example: 103 bytes written
I (15955) example: Reading HTTP response...
HTTP/1.1 200 OK
Date: Tue, 24 Mar 2020 12:05:03 GMT
Server: Apache/2.4.37 (centos) OpenSSL/1.1.1c mod_fcgid/2.3.9
Last-Modified: Thu, 12 Mar 2020 18:08:25 GMT
ETag: "15-xxxx"
Accept-Ranges: bytes
Content-Length: 21
Connection: close
Content-Type: text/html; charset=UTF-8

<html>...</html>

I (15995) example: Completed 2 requests
I (15995) example: 10...
...
I (25995) example: 0...
I (26995) example: Starting again!
W (26995) example: Free Heap: 202984 <<----------------------------------------
I (26995) example: Connecting to 192.168.168.XX:443...
I (27005) example: Connected.
I (27005) example: Performing the SSL/TLS handshake...
I (27135) esp-x509-crt-bundle: Certificate validated
I (28115) example: Verifying peer X.509 certificate...
I (28125) example: Certificate verified.
I (28125) example: Cipher suite is TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384
I (28125) example: Writing HTTP request...
I (28135) example: 103 bytes written
I (28135) example: Reading HTTP response...
HTTP/1.1 200 OK
Date: Tue, 24 Mar 2020 12:05:15 GMT
Server: Apache/2.4.37 (centos) OpenSSL/1.1.1c mod_fcgid/2.3.9
Last-Modified: Thu, 12 Mar 2020 18:08:25 GMT
ETag: "15-xxxx"
Accept-Ranges: bytes
Content-Length: 21
Connection: close
Content-Type: text/html; charset=UTF-8

<html>...</html>

I (28195) example: Completed 3 requests
I (28195) example: 10...
...
I (38195) example: 0...
I (39195) example: Starting again!
W (39195) example: Free Heap: 201760 <<----------------------------------------
I (39195) example: Connecting to 192.168.168.XX:443...
I (39205) example: Connected.
I (39205) example: Performing the SSL/TLS handshake...
I (39325) esp-x509-crt-bundle: Certificate validated
I (40315) example: Verifying peer X.509 certificate...
I (40315) example: Certificate verified.
I (40315) example: Cipher suite is TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384
I (40325) example: Writing HTTP request...
I (40325) example: 103 bytes written
I (40335) example: Reading HTTP response...
HTTP/1.1 200 OK
Date: Tue, 24 Mar 2020 12:05:27 GMT
Server: Apache/2.4.37 (centos) OpenSSL/1.1.1c mod_fcgid/2.3.9
Last-Modified: Thu, 12 Mar 2020 18:08:25 GMT
ETag: "15-xxxx"
Accept-Ranges: bytes
Content-Length: 21
Connection: close
Content-Type: text/html; charset=UTF-8

<html>...</html>

I (40365) example: Completed 4 requests
I (40365) example: 10...
...
I (50375) example: 0...
I (51375) example: Starting again!
W (51375) example: Free Heap: 200532 <<----------------------------------------
I (51375) example: Connecting to 192.168.168.XX:443...
I (51385) example: Connected.
I (51385) example: Performing the SSL/TLS handshake...
I (51525) esp-x509-crt-bundle: Certificate validated
I (52545) example: Verifying peer X.509 certificate...
I (52545) example: Certificate verified.
I (52545) example: Cipher suite is TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384
I (52545) example: Writing HTTP request...
I (52555) example: 103 bytes written
I (52555) example: Reading HTTP response...
HTTP/1.1 200 OK
Date: Tue, 24 Mar 2020 12:05:39 GMT
Server: Apache/2.4.37 (centos) OpenSSL/1.1.1c mod_fcgid/2.3.9
Last-Modified: Thu, 12 Mar 2020 18:08:25 GMT
ETag: "15-xxxx"
Accept-Ranges: bytes
Content-Length: 21
Connection: close
Content-Type: text/html; charset=UTF-8

<html>...</html>

I (52595) example: Completed 5 requests
I (52595) example: 10...
...
I (62595) example: 0...
I (63595) example: Starting again!
W (63595) example: Free Heap: 199308 <<----------------------------------------
I (63595) example: Connecting to 192.168.168.XX:443...
I (63605) example: Connected.
I (63605) example: Performing the SSL/TLS handshake...
I (63715) esp-x509-crt-bundle: Certificate validated
I (64705) example: Verifying peer X.509 certificate...
I (64705) example: Certificate verified.
I (64705) example: Cipher suite is TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384
I (64705) example: Writing HTTP request...
I (64715) example: 103 bytes written
I (64715) example: Reading HTTP response...
HTTP/1.1 200 OK
Date: Tue, 24 Mar 2020 12:05:52 GMT
Server: Apache/2.4.37 (centos) OpenSSL/1.1.1c mod_fcgid/2.3.9
Last-Modified: Thu, 12 Mar 2020 18:08:25 GMT
ETag: "15-xxxx"
Accept-Ranges: bytes
Content-Length: 21
Connection: close
Content-Type: text/html; charset=UTF-8

<html>...</html>

I (64755) example: Completed 6 requests
I (64755) example: ...

If you see the heap size, we lose ~2000 bytes on every requests.

W (2715) example: Free Heap: 206168
W (14855) example: Free Heap: 204212
W (26995) example: Free Heap: 202984
W (39195) example: Free Heap: 201760
W (51375) example: Free Heap: 200532
W (63595) example: Free Heap: 199308

The example work fine without custom certificate, this problem is only when adding custom x509 root certificate by menuconfig

#
# Certificate Bundle
#
CONFIG_MBEDTLS_CERTIFICATE_BUNDLE=y
CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_FULL=y
# CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_CMN is not set
# CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_NONE is not set
CONFIG_MBEDTLS_CUSTOM_CERTIFICATE_BUNDLE=y
CONFIG_MBEDTLS_CUSTOM_CERTIFICATE_BUNDLE_PATH="/home/me/Desktop/server_root_cert.pem"
# end of Certificate Bundle

Thank you,

Source

dragahassan

All 12 comments

After debugging line by line, I found that mbedtls_net_free() do nothing!

Request 1
mbedtls_net_connect() --> Connect, and allocate memory.
mbedtls_net_free() --> Successful execution, but allocation in memory still exist.

Request 2
mbedtls_net_connect() --> Connect, and allocate memory in new area (of course).
mbedtls_net_free() --> Successful execution, but allocation in memory still exist!.

Can someone explain why?

dragahassan on 24 Mar 2020

You might be seeing the TCP active close behavior? https://github.com/espressif/esp-idf/issues/2134#issuecomment-403336387

Please check if the heap returns back to normal after a few minutes.

igrr on 24 Mar 2020

😕1 👍1

That's it, the socket standard is keep it open for a while, I will test it by reducing the maximum opened socket and see if it's work.

Thank you Grokhotkov for your help.

dragahassan on 24 Mar 2020

Unfortunately didn't work, I set those settings :

# LWIP
CONFIG_LWIP_MAX_SOCKETS=1
# TCP
CONFIG_LWIP_MAX_ACTIVE_TCP=1
CONFIG_LWIP_MAX_LISTENING_TCP=1

I sent some requests yesterday, and others this morning, it's seem heap memory keep shrinking!

dragahassan on 25 Mar 2020

Note: The only change I made in the default mbedTLS example is :

Disable Mozilla default trusted CA & Add my custom certificate

CONFIG_MBEDTLS_CERTIFICATE_BUNDLE=y
# CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_FULL is not set
# CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_CMN is not set
CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_NONE=y
CONFIG_MBEDTLS_CUSTOM_CERTIFICATE_BUNDLE=y
CONFIG_MBEDTLS_CUSTOM_CERTIFICATE_BUNDLE_PATH="/home/me/Desktop/my_root_cert.pem"

Add sample Log to show available heap

...
if ((ret = mbedtls_ssl_setup(&ssl, &conf)) != 0)
{
   ESP_LOGE(TAG, "mbedtls_ssl_setup returned -0x%x\n\n", -ret);
   goto exit;
}
while(1){
   ESP_LOGE(TAG, "Heap: %d", esp_get_free_heap_size());
   ...
}

dragahassan on 25 Mar 2020

@hassance3 Thanks for reporting this. You are right, there is a leak here. I'll push a merge request for it.

I'll attach a patch in case you want a fix asap.
crt_mem_leak.txt

ESP-Marius on 26 Mar 2020

👍1

@ESP-Marius I confirm that the issue is fixed, Thank you Marius.

Can you please give me the merge request ? I want keep it for reference.
Thank you,

dragahassan on 26 Mar 2020

@igrr Please can you give me the merge request ? this solve the memory leak issue.

dragahassan on 27 Mar 2020

@hassance3 The merge request is in review in our internal repository and will be merged after it passes the tests. This issue will be automatically closed when the fix lands on Github. This should happen in the next few work days.
In the meantime, please use the patch provided by @ESP-Marius locally as a fix, if possible.

igrr on 27 Mar 2020

@igrr I already used the patch provided by @ESP-Marius , I would like just sign that the path it's worked for me.

Thank you for you support,
Sincerely.

dragahassan on 27 Mar 2020

While you're reviewing it, could you also import the changes in mbedtls dev branch that prevents copying certificates in the heap (see here)

Certificate tends to be large, and idf is quite dumb with handling them. The automated build system should store certificate in DER format (and not PEM since it's 33% larger being base64 encoded) when making the asm sections. Also the mbedtls version used in esp-idf/component copies the given certificate in the heap because it "might need it later", which, as far as I know, is a useless copy when the certificate is in flash (it'll stay here).

If your certificate chain is large (mine is 24kB) that does make a big difference in the end (16kB instead of ~48kB used in heap, and 16kB instead of 24kB in flash).

X-Ryl669 on 27 Mar 2020

👍1

@X-Ryl669 Thanks for reporting and follow up. The fix in our internal repo. has been merged, the issue will be automatically closed when the fix lands on Github. For your information, thanks.