imap.connect() encounters error (mbedtls) and consumes heap at (re)connect

Question

imap.connect() encounters error (mbedtls) and consumes heap at (re)connect

dkalliv opened this issue a year ago · 5 comments

dkalliv commented a year ago

Build tool used:

Arudino
Platformio (Visual Studio Code plugin)
Platformio CLI
Other

Board used (ESP32/ESP8266/Arudino):

ESP8266-based
ESP32-based

Other Libraries That are used:

Description of problem:
I noticed, that sometimes my heap is significantly lower either right after starting a program or when the imap server is reconnected (for example after a WiFi disconnect). After some research I noticed, that sometimes the imap.connect() reports the error "_esp32_ssl_handle_error(): [send_ssl_data():545]: (-27136) SSL - A buffer is too small to receive or write a message" (I guess this is from mbedtls) and the retries. Every time this happens I loose roughly 34k of heap memory. In a weak WiFi network the heap is quickly depleted.
The code below does just open a imap connection and reconnects, after a network interruption. After a few reconnects the issue appears, sometimes already with the initial connection. Do you have any idea how to prevent this or how to release the memory occupied?
Share code snippet to reproduce the issue:

#include <Arduino.h>
#include <WiFi.h>
#include <ESP_Mail_Client.h>
#include <extras/SDHelper.h>

#define WIFI_SSID "*********"
#define WIFI_PASSWORD "********"

#define IMAP_HOST "imapserver"
#define IMAP_PORT 993

#define AUTHOR_EMAIL "****@*********"
#define AUTHOR_PASSWORD "*********"

IMAPSession imap;

unsigned long readMillis = 0;
int totalMessage = 0;
int msgNum = 0;
int sign = -1;

Session_Config config;

IMAP_Data imap_data;

#if defined(ARDUINO_RASPBERRY_PI_PICO_W)
WiFiMulti multi;
#endif

// For Free Heap checking
#include "HeapStat.h"
HeapStat heapInfo;

void setup()
{
    Serial.begin(115200);
    Serial.println();
    WiFi.begin(WIFI_SSID, WIFI_PASSWORD);
    Serial.print("Connecting to Wi-Fi");
    while (WiFi.status() != WL_CONNECTED)
    {
        Serial.print(".");
        delay(300);

    }
    Serial.println();
    Serial.print("Connected with IP: ");
    Serial.println(WiFi.localIP());
    Serial.println();
    MailClient.networkReconnect(true);
    imap.debug(1);
    config.server.host_name = IMAP_HOST;
    config.server.port = IMAP_PORT;
    config.login.email = AUTHOR_EMAIL;
    config.login.password = AUTHOR_PASSWORD;

    /* Message UID to fetch or read */
    imap_data.fetch.uid.clear();

    /* Search criteria */
    imap_data.search.criteria.clear();

    /* Also search the unseen message */
    imap_data.search.unseen_msg = true;
    imap_data.storage.saved_path = F("/email_data");
    imap_data.storage.type = esp_mail_file_storage_type_none;
    imap_data.download.header = false;
    imap_data.download.text = false;
    imap_data.download.html = false;
    imap_data.download.attachment = false;
    imap_data.download.inlineImg = false;
    imap_data.enable.html = true;
    imap_data.enable.text = true;
    imap_data.enable.recent_sort = true;
    imap_data.enable.download_status = true;
    imap_data.limit.search = 5;
    imap_data.limit.msg_size = 512;
    imap_data.limit.attachment_size = 1024 * 1024 * 5;

    /* Connect to the server */
    if (!imap.connect(&config, &imap_data))
        return;

    if (!imap.isLoggedIn())
    {
        Serial.println("\nNot yet logged in.");
    }
    else
    {
        if (imap.isAuthenticated())
            Serial.println("\nSuccessfully logged in.");
        else
            Serial.println("\nConnected with no Auth.");
    }
        heapInfo.collect();
        heapInfo.print();
}

void loop()
{
    if (millis() - readMillis > 10000 || readMillis == 0)
    {
        readMillis = millis();
        // If session was closed, reconnect and re-select the mailbox
        if (!imap.connected())
        {
            if (!imap.connect(&config, &imap_data))
                return;
            if (!imap.selectFolder(F("INBOX")))
                return;
        }
        imap.empty();
        heapInfo.collect();
        heapInfo.print();
    }
}

Additional information and things you've tried:
Here is the console log:

ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_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:1
load:0x3fff0030,len:1184
load:0x40078000,len:13220
ho 0 tail 12 room 4
load:0x40080400,len:3028
entry 0x400805e4
[     5][D][esp32-hal-cpu.c:244] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz

[    36][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 0 - WIFI_READY
[   125][V][WiFiGeneric.cpp:97] set_esp_interface_ip(): Configuring Station static IP: 0.0.0.0, MASK: 0.0.0.0, GW: 0.0.0.0
[   123][V][WiFiGeneric.cpp:340] _arduino_event_cb(): STA Started
[   131][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 2 - STA_START
Connecting to Wi-Fi.[   349][V][WiFiGeneric.cpp:355] _arduino_event_cb(): STA Connected: SSID: MYSSID, BSSID: 00:00:00:00:00:00, Channel: 6, Auth: WPA2_PSK
[   351][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 4 - STA_CONNECTED
[   369][V][WiFiGeneric.cpp:369] _arduino_event_cb(): STA Got New IP:172.20.10.10
[   369][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 7 - STA_GOT_IP
[   373][D][WiFiGeneric.cpp:1098] _eventCallback(): STA IP: 172.20.10.10, MASK: 255.255.255.240, GW: 172.20.10.1

Connected with IP: 172.20.10.10

> C: ESP Mail Client v3.1.13
> C: connecting to IMAP server
> C: Host > imapserver
> C: Port > 993

> C: SSL/TLS negotiation
> C: seeding the random number generator
[  1061][V][ESP32_SSL_Client.cpp:201] connect_ssl(): Seeding the random number generator
> C: setting up the SSL/TLS structure
[  1075][V][ESP32_SSL_Client.cpp:220] connect_ssl(): Setting up the SSL/TLS structure...
! W: Skipping SSL Verification. INSECURE!
[  1086][I][ESP32_SSL_Client.cpp:244] connect_ssl(): WARNING: Skipping SSL Verification. INSECURE!
> C: setting hostname for TLS session
[  1097][V][ESP32_SSL_Client.cpp:387] connect_ssl(): Setting hostname for TLS session...
> C: perform the SSL/TLS handshake
[  1109][V][ESP32_SSL_Client.cpp:417] connect_ssl(): Performing the SSL/TLS handshake...
> C: verifying peer X.509 certificate
[  4441][V][ESP32_SSL_Client.cpp:456] connect_ssl(): Verifying peer X.509 certificate...
[  4441][V][ESP32_SSL_Client.cpp:472] connect_ssl(): Certificate verified.
[  4448][V][ESP32_SSL_Client.cpp:491] connect_ssl(): Free internal heap after TLS 205740

> C: IMAP server connected

> C: check the capability
[  4467][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 16 bytes...
[  4470][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...

> C: send IMAP command, AUTHENTICATE PLAIN
[  5079][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 73 bytes...
[  5081][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...

> C: send IMAP command, ID
[  5671][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 54 bytes...
[  5673][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...

Successfully logged in.
#### Heap Info
#### Current: 205596, Min: 205596, Max: 205596, Diff_1: 0, Diff_1: 0
#### Heap Info
#### Current: 205736, Min: 205596, Max: 205736, Diff_1: 140, Diff_2: 140
#### Heap Info
#### Current: 205736, Min: 205596, Max: 205736, Diff_1: 140, Diff_3: 0
#### Heap Info
#### Current: 205736, Min: 205596, Max: 205736, Diff_1: 140, Diff_4: 0
[ 26762][V][WiFiGeneric.cpp:362] _arduino_event_cb(): STA Disconnected: SSID: MYSSID, BSSID: 00:00:00:00:00:00, Reason: 200
[ 26763][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 5 - STA_DISCONNECTED
[ 26771][W][WiFiGeneric.cpp:1057] _eventCallback(): Reason: 200 - BEACON_TIMEOUT
[ 26778][D][WiFiGeneric.cpp:1077] _eventCallback(): WiFi Reconnect Running
[ 26786][V][WiFiGeneric.cpp:97] set_esp_interface_ip(): Configuring Station static IP: 0.0.0.0, MASK: 0.0.0.0, GW: 0.0.0.0
[ 26975][V][WiFiGeneric.cpp:355] _arduino_event_cb(): STA Connected: SSID: MYSSID, BSSID: e6:db:c1:8d:ed:45, Channel: 6, Auth: WPA2_PSK
[ 26978][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 4 - STA_CONNECTED
[ 27531][V][WiFiGeneric.cpp:369] _arduino_event_cb(): STA Got Same IP:172.20.10.10
[ 27532][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 7 - STA_GOT_IP
[ 27535][D][WiFiGeneric.cpp:1098] _eventCallback(): STA IP: 172.20.10.10, MASK: 255.255.255.240, GW: 172.20.10.1
[ 36302][D][WiFiClient.cpp:546] connected(): Disconnected: RES: -1, ERR: 113
> C: ESP Mail Client v3.1.13
> C: connecting to IMAP server
> C: Host > imapserver
> C: Port > 993

> C: SSL/TLS negotiation
> C: seeding the random number generator
[ 37216][V][ESP32_SSL_Client.cpp:201] connect_ssl(): Seeding the random number generator
> C: setting up the SSL/TLS structure
[ 37230][V][ESP32_SSL_Client.cpp:220] connect_ssl(): Setting up the SSL/TLS structure...
! W: Skipping SSL Verification. INSECURE!
[ 37241][I][ESP32_SSL_Client.cpp:244] connect_ssl(): WARNING: Skipping SSL Verification. INSECURE!
> C: setting hostname for TLS session
[ 37253][V][ESP32_SSL_Client.cpp:387] connect_ssl(): Setting hostname for TLS session...
> C: perform the SSL/TLS handshake
[ 37264][V][ESP32_SSL_Client.cpp:417] connect_ssl(): Performing the SSL/TLS handshake...
> C: verifying peer X.509 certificate
[ 37275][V][ESP32_SSL_Client.cpp:456] connect_ssl(): Verifying peer X.509 certificate...
[ 37276][V][ESP32_SSL_Client.cpp:472] connect_ssl(): Certificate verified.
[ 37282][V][ESP32_SSL_Client.cpp:491] connect_ssl(): Free internal heap after TLS 170892

> C: IMAP server connected

> C: check the capability
[ 39290][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 16 bytes...
[ 39292][V][ESP32_SSL_Client.cpp:543] send_ssl_data(): Handling error -27136
[ 39298][E][ESP32_SSL_Client.cpp:63] _esp32_ssl_handle_error(): [send_ssl_data():545]: (-27136) SSL - A buffer is too small to receive or write a message
> C: cleaning SSL connection
[ 39322][V][ESP32_SSL_Client.cpp:503] stop_tcp_connection(): Cleaning SSL connection.
! E: data sending failed
> C: ESP Mail Client v3.1.13
> C: connecting to IMAP server
> C: Host > imapserver
> C: Port > 993

> C: SSL/TLS negotiation
> C: seeding the random number generator
[ 47049][V][ESP32_SSL_Client.cpp:201] connect_ssl(): Seeding the random number generator
> C: setting up the SSL/TLS structure
[ 47063][V][ESP32_SSL_Client.cpp:220] connect_ssl(): Setting up the SSL/TLS structure...
! W: Skipping SSL Verification. INSECURE!
[ 47074][I][ESP32_SSL_Client.cpp:244] connect_ssl(): WARNING: Skipping SSL Verification. INSECURE!
> C: setting hostname for TLS session
[ 47086][V][ESP32_SSL_Client.cpp:387] connect_ssl(): Setting hostname for TLS session...
> C: perform the SSL/TLS handshake
[ 47097][V][ESP32_SSL_Client.cpp:417] connect_ssl(): Performing the SSL/TLS handshake...
> C: verifying peer X.509 certificate
[ 50222][V][ESP32_SSL_Client.cpp:456] connect_ssl(): Verifying peer X.509 certificate...
[ 50222][V][ESP32_SSL_Client.cpp:472] connect_ssl(): Certificate verified.
[ 50229][V][ESP32_SSL_Client.cpp:491] connect_ssl(): Free internal heap after TLS 172160

> C: IMAP server connected

> C: check the capability
[ 50248][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 16 bytes...
[ 50252][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...

> C: send IMAP command, AUTHENTICATE PLAIN
[ 50760][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 73 bytes...
[ 50762][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...

> C: send IMAP command, ID
[ 51349][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 54 bytes...
[ 51351][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...

> C: selecting the INBOX folder...
[ 51975][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 21 bytes...
[ 51978][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...
#### Heap Info
#### Current: 171492, Min: 171492, Max: 205736, Diff_1: -34104, Diff_5: -34244

Answer 1 · 2023-07-07T01:52:36.000Z

Ok I see some strange issue after network disconnected and trying to reconnect.

Answer 2 · 2023-07-07T04:16:29.000Z

Now this issue was fixed in v3.1.14.

Thanks for reporting this.

Answer 3 · 2023-07-07T18:15:16.000Z

Hi mobizt, thank you for the fix, unfortunately the issue still exists (see log). Maybe it even got worse (occurs more frequently), but this might be just a coincidence. Can this even be fixed in your library (which I like very much!) or does this have to by fixed in the Arduino core for the ESP32 (defining MBEDTLS_SSL_VARIABLE_BUFFER_LENGTH or maybe MBEDTLS_SSL_MAX_CONTENT_LEN)?

Here is the log from my last test:

...
#### Heap Info
#### Current: 205012, Min: 205012, Max: 205788, Diff_1: -624, Diff_10: 0
[124074][V][WiFiGeneric.cpp:362] _arduino_event_cb(): STA Disconnected: SSID: SSID, BSSID: 00:00:00:00:00:00, Reason: 200
[124075][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 5 - STA_DISCONNECTED
[124083][W][WiFiGeneric.cpp:1057] _eventCallback(): Reason: 200 - BEACON_TIMEOUT
[124090][D][WiFiGeneric.cpp:1081] _eventCallback(): WiFi AutoReconnect Running
[124099][V][WiFiGeneric.cpp:97] set_esp_interface_ip(): Configuring Station static IP: 0.0.0.0, MASK: 0.0.0.0, GW: 0.0.0.0
[124593][V][WiFiGeneric.cpp:355] _arduino_event_cb(): STA Connected: SSID: SSID, BSSID: 00:00:00:00:00:00, Channel: 6, Auth: WPA2_PSK
[124595][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 4 - STA_CONNECTED
[125117][V][WiFiGeneric.cpp:369] _arduino_event_cb(): STA Got Same IP:172.20.10.10
[125118][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 7 - STA_GOT_IP
[125121][D][WiFiGeneric.cpp:1098] _eventCallback(): STA IP: 172.20.10.10, MASK: 255.255.255.240, GW: 172.20.10.1
[126953][D][WiFiClient.cpp:546] connected(): Disconnected: RES: -1, ERR: 113
> C: ESP Mail Client v3.1.14
> C: connecting to IMAP server
> C: Host > mailserver
> C: Port > 993

> C: SSL/TLS negotiation
> C: seeding the random number generator
[127293][V][ESP32_SSL_Client.cpp:201] connect_ssl(): Seeding the random number generator
> C: setting up the SSL/TLS structure
[127307][V][ESP32_SSL_Client.cpp:220] connect_ssl(): Setting up the SSL/TLS structure...
! W: Skipping SSL Verification. INSECURE!
[127317][I][ESP32_SSL_Client.cpp:244] connect_ssl(): WARNING: Skipping SSL Verification. INSECURE!
> C: setting hostname for TLS session
[127329][V][ESP32_SSL_Client.cpp:387] connect_ssl(): Setting hostname for TLS session...
> C: perform the SSL/TLS handshake
[127341][V][ESP32_SSL_Client.cpp:417] connect_ssl(): Performing the SSL/TLS handshake...
> C: verifying peer X.509 certificate
[127351][V][ESP32_SSL_Client.cpp:456] connect_ssl(): Verifying peer X.509 certificate...
[127352][V][ESP32_SSL_Client.cpp:472] connect_ssl(): Certificate verified.
[127359][V][ESP32_SSL_Client.cpp:491] connect_ssl(): Free internal heap after TLS 170152

> C: IMAP server connected

> C: check the capability
[129367][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 16 bytes...
[129369][V][ESP32_SSL_Client.cpp:543] send_ssl_data(): Handling error -27136
[129375][E][ESP32_SSL_Client.cpp:63] _esp32_ssl_handle_error(): [send_ssl_data():545]: (-27136) SSL - A buffer is too small to receive or write a message
> C: cleaning SSL connection
[129399][V][ESP32_SSL_Client.cpp:503] stop_tcp_connection(): Cleaning SSL connection.
! E: data sending failed
> C: ESP Mail Client v3.1.14
> C: connecting to IMAP server
> C: Host > mailserver
> C: Port > 993

> C: SSL/TLS negotiation
> C: seeding the random number generator
[137737][V][ESP32_SSL_Client.cpp:201] connect_ssl(): Seeding the random number generator
> C: setting up the SSL/TLS structure
[137751][V][ESP32_SSL_Client.cpp:220] connect_ssl(): Setting up the SSL/TLS structure...
! W: Skipping SSL Verification. INSECURE!
[137761][I][ESP32_SSL_Client.cpp:244] connect_ssl(): WARNING: Skipping SSL Verification. INSECURE!
> C: setting hostname for TLS session
[137773][V][ESP32_SSL_Client.cpp:387] connect_ssl(): Setting hostname for TLS session...
> C: perform the SSL/TLS handshake
[137785][V][ESP32_SSL_Client.cpp:417] connect_ssl(): Performing the SSL/TLS handshake...
> C: verifying peer X.509 certificate
[140708][V][ESP32_SSL_Client.cpp:456] connect_ssl(): Verifying peer X.509 certificate...
[140708][V][ESP32_SSL_Client.cpp:472] connect_ssl(): Certificate verified.
[140715][V][ESP32_SSL_Client.cpp:491] connect_ssl(): Free internal heap after TLS 171468

> C: IMAP server connected

> C: check the capability
[140734][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 16 bytes...
[140737][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...

> C: send IMAP command, AUTHENTICATE PLAIN
[141655][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 73 bytes...
[141657][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...

> C: send IMAP command, ID
[142245][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 54 bytes...
[142247][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...

> C: selecting the INBOX folder...
[142871][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 21 bytes...
[142874][V][ESP32_SSL_Client.cpp:534] send_ssl_data(): Writing request with 2 bytes...
#### Heap Info
#### Current: 171448, Min: 171448, Max: 205788, Diff_1: -34188, Diff_11: -33564

Answer 4 · 2023-07-08T06:41:31.000Z

You said true, after intensively test by moving router away from device.

This happens only in case MailClient.readMail or MailClient.sendMail was not called to handle network reconnection and free resources.

The resources are not released properly when calling imap.connect repeatedly.

Now the issue was fixed in v3.1.15, please update.

Unlike BearSSL used in ESP8266, mbedTLS data and SSL buffer cannot change without modifying the sources and recompiling the core library.

The SSL buffer should not change as IMAP server requires 16k buffer to work because it not supports fragmentation.

That's why we need to increase the in buffer to 16k for working with IMAP.

Answer 5 · 2023-07-08T21:35:34.000Z

Thank you, this now works perfectly! Thank you as well for your explanation, I now understand, what the issue was and that the buffer in libmbedtls is already set to the maximum of 16k...
Keep up the great work!