Esp-idf: BUG in esp_http_client when using HTTPS and receiving error ESP_ERR_HTTP_FETCH_HEADER (IDFGH-449)

[lrodenasSistel]

Environment

Own product pcb using:

• Module or chip used: ESP32-WROVER
• IDF version 3.1.1
• Build System: [Make]
• Compiler version: xtensa-esp32-elf-gcc.exe (crosstool-NG crosstool-ng-1.22.0-80-g6c4433a5) 5.2.0
• Operating System: [Windows]
• Power Supply: [USB and/or Battery]

Problem Description

I think I found an important bug in esp_http_client. It only happens when using HTTPS.

I do several https requests in the same session, if one of them fails with error ESP_ERR_HTTP_FETCH_HEADER, client buffer seems to break and next https requests receive the incorrect response with the events.
It's like the one failing is still buffered but not processed, and its response is given with the next request performed.

I find it quite hard to explain, I went crazy trying to find this because I believed it was in my code.
Please check following log picture and code sample to reproduce it.

I found a workaround, puting esp_http_client_close(client); every time the http perform returns an error. But I think this forces to redo the SSL handshake in the next request, wasting CPU time.

Other minor things I found:
The http_error event is never fired even if there is an error while performing the request.
Sometimes if one request fails (when touching with finger as described next), it makes the following ones to fail, maybe the next 2 or 3, but they shouldnt fail because finger is already removed... this only happens sometimes, but once with real error (no finger) it provoked following 10 minutes of request failing, until at some point the http client disconnected and reconnected again and everything went fine from there.

Please let me know if you need any more details. 😃

Expected Behavior

When https request fails with any error, I expect this does not affect next requests.

Actual Behavior

As you can see in the following picture, or check with sample code, I do 2 requests, 1 POST and 1 GET. Before error POST always receives answer of 404 bytes, GET receives answer of 289 bytes. That is correct.
After the error you can see that the answers are switched, when I do GET I am getting the POST answer and viceversa.
You can also check the date header received, which is wrong and repeated the same.
Sometimes if you leave finger touching (described next) during 2-3 requests that fail, then the following requests all receive the same date header for 2-3 times.
Not only the headers are switched, the answer itself is also switched with the previous request.

Steps to reproduce

This issue needs the https request to fail and timeout, which happens more or less twice a day in my environment.
But I discovered a way to force it happen.
While code is runing, touch with your finger the Wrover module in the pad 1 GND corner, touching at the same time the pcb antenna, the shield, and the GND pad or its decoupling capacitor.
It takes some trial and error but at some point https requests fail while you have the finger touching, so you have to keep touching until the request times out and the error appears.
If you touch for too long, error shows several times but at some point the http client launches a disconnect event and this fixes the error (that's how I based my workaround).
I found that sometimes the finger trick does not work anymore and I needed to restart ESP32 (without touching at the same time) in order for it to work again.

Code to reproduce this issue

Code is based on esp_http_client example, just removing what is not needed and with minor modifications. Default sdkconfig for this example, just changed serial port and wifi credentials.

#include <string.h>
#include <stdlib.h>
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "esp_log.h"
#include "esp_system.h"
#include "nvs_flash.h"
#include "app_wifi.h"

#include "esp_http_client.h"

#define MAX_HTTP_RECV_BUFFER 512
static const char *TAG = "HTTP_CLIENT";

extern const char howsmyssl_com_root_cert_pem_start[] asm("_binary_howsmyssl_com_root_cert_pem_start");
extern const char howsmyssl_com_root_cert_pem_end[]   asm("_binary_howsmyssl_com_root_cert_pem_end");

esp_err_t _http_event_handler(esp_http_client_event_t *evt)
{
    switch(evt->event_id) {
        case HTTP_EVENT_ERROR:
            ESP_LOGI(TAG, "HTTP_EVENT_ERROR");
            break;
        case HTTP_EVENT_ON_CONNECTED:
            ESP_LOGI(TAG, "HTTP_EVENT_ON_CONNECTED");
            break;
        case HTTP_EVENT_HEADER_SENT:
            ESP_LOGI(TAG, "HTTP_EVENT_HEADER_SENT");
            break;
        case HTTP_EVENT_ON_HEADER:
            ESP_LOGI(TAG, "HTTP_EVENT_ON_HEADER, key=%s, value=%s", evt->header_key, evt->header_value);
            break;
        case HTTP_EVENT_ON_DATA:
            ESP_LOGI(TAG, "HTTP_EVENT_ON_DATA, len=%d", evt->data_len);
            if (!esp_http_client_is_chunked_response(evt->client)) {
                // Write out data
                // printf("%.*s", evt->data_len, (char*)evt->data);
            }

            break;
        case HTTP_EVENT_ON_FINISH:
            ESP_LOGI(TAG, "HTTP_EVENT_ON_FINISH");
            break;
        case HTTP_EVENT_DISCONNECTED:
            ESP_LOGI(TAG, "HTTP_EVENT_DISCONNECTED");
            break;
    }
    return ESP_OK;
}

static void http_rest()
{
    esp_http_client_config_t config = {
        .url = "https://httpbin.org/get",
        .event_handler = _http_event_handler,
        .cert_pem = howsmyssl_com_root_cert_pem_start,
    };
    esp_http_client_handle_t client = esp_http_client_init(&config);

    while(1)
    {
        // GET
        esp_http_client_set_url(client, "https://httpbin.org/get");
        esp_http_client_set_method(client, HTTP_METHOD_GET);
        esp_err_t err = esp_http_client_perform(client);
        if (err == ESP_OK) {
            ESP_LOGI(TAG, "HTTP GET Status = %d, content_length = %d\n",
                    esp_http_client_get_status_code(client),
                    esp_http_client_get_content_length(client));
        } else {
            ESP_LOGE(TAG, "HTTP GET request failed: %s", esp_err_to_name(err));
        }

        vTaskDelay(1000 / portTICK_PERIOD_MS);

        // POST
        const char *post_data = "field1=value1&field2=value2";
        esp_http_client_set_url(client, "https://httpbin.org/post");
        esp_http_client_set_method(client, HTTP_METHOD_POST);
        esp_http_client_set_post_field(client, post_data, strlen(post_data));
        err = esp_http_client_perform(client);
        if (err == ESP_OK) {
            ESP_LOGI(TAG, "HTTP POST Status = %d, content_length = %d\n",
                    esp_http_client_get_status_code(client),
                    esp_http_client_get_content_length(client));
        } else {
            ESP_LOGE(TAG, "HTTP POST request failed: %s", esp_err_to_name(err));
        }

        vTaskDelay(1000 / portTICK_PERIOD_MS);
    }
}

static void http_test_task(void *pvParameters)
{
    app_wifi_wait_connected();
    ESP_LOGI(TAG, "Connected to AP, begin http example");
    http_rest();
}

void app_main()
{
    esp_err_t ret = nvs_flash_init();
    if (ret == ESP_ERR_NVS_NO_FREE_PAGES || ret == ESP_ERR_NVS_NEW_VERSION_FOUND) {
      ESP_ERROR_CHECK(nvs_flash_erase());
      ret = nvs_flash_init();
    }
    ESP_ERROR_CHECK(ret);
    app_wifi_initialise();

    xTaskCreate(&http_test_task, "http_test_task", 8192, NULL, 5, NULL);
}

[jitin17]

Hi @lrodenasSistel, I am including a text file(change the extension to .patch), which contains patch of workaround for this issue.
Apply the patch, and let us know if that works.

client_workaround_patch.txt

[lrodenasSistel]

How do I apply the patch? Where should I put this file after changing the extension?

[jitin17]

Instead of applying patch, I am sending you modified esp_http_client_perform() API in the text file.
So can you replace the existing esp_http_client_perform() API in components/esp_http_client.c with the one given in the text file?
Let us know if this works. I am finding it a little difficult to reproduce the issue. So, if this works then we can raise an MR to fix the bug.

new_esp_http_perform_api.txt

[lrodenasSistel]

I get compilation errors just replacing that function. I am using IDF3.1.1.
Did you manage to reproduce the issue at least once?
I can reproduce it at will with the sample code I posted and touching the wrover module antena.

Running make app-flash...
CC build/esp_http_client/esp_http_client.o
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c: In function 'esp_http_client_perform':
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:779:28: error: implicit declaration of function 'esp_http_client_connect' [-Werror=implicit-function-declaration]
                 if ((err = esp_http_client_connect(client)) != ESP_OK) {
                            ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:780:31: error: 'struct esp_http_client' has no member named 'is_async'
                     if (client->is_async && err == ESP_ERR_HTTP_CONNECTING) {
                               ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:780:52: error: 'ESP_ERR_HTTP_CONNECTING' undeclared (first use in this function)
                     if (client->is_async && err == ESP_ERR_HTTP_CONNECTING) {
                                                    ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:780:52: note: each undeclared identifier is reported only once for each function it appears in
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:781:32: error: 'ESP_ERR_HTTP_EAGAIN' undeclared (first use in this function)
                         return ESP_ERR_HTTP_EAGAIN;
                                ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:787:28: error: implicit declaration of function 'esp_http_client_request_send' [-Werror=implicit-function-declaration]
                 if ((err = esp_http_client_request_send(client)) != ESP_OK) {
                            ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:788:31: error: 'struct esp_http_client' has no member named 'is_async'
                     if (client->is_async && errno == EAGAIN) {
                               ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:788:45: error: 'errno' undeclared (first use in this function)
                     if (client->is_async && errno == EAGAIN) {
                                             ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:788:54: error: 'EAGAIN' undeclared (first use in this function)
                     if (client->is_async && errno == EAGAIN) {
                                                      ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:795:28: error: implicit declaration of function 'esp_http_client_send_post_data' [-Werror=implicit-function-declaration]
                 if ((err = esp_http_client_send_post_data(client)) != ESP_OK) {
                            ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:796:31: error: 'struct esp_http_client' has no member named 'is_async'
                     if (client->is_async && errno == EAGAIN) {
                               ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:805:31: error: 'struct esp_http_client' has no member named 'is_async'
                     if (client->is_async && errno == EAGAIN) {
                               ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:820:35: error: 'struct esp_http_client' has no member named 'is_async'
                         if (client->is_async && errno == EAGAIN) {
                                   ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:829:35: error: 'struct esp_http_client' has no member named 'is_async'
                         if (client->is_async && errno == EAGAIN) {
                                   ^
C:/DESARROLLO/ESP32/esp-idf/components/esp_http_client/esp_http_client.c:844:31: error: 'struct esp_http_client' has no member named 'first_line_prepared'
                         client->first_line_prepared = false;
                               ^
cc1.exe: some warnings being treated as errors
make[2]: *** [/c/DESARROLLO/ESP32/esp-idf/make/component_wrapper.mk:286: esp_http_client.o] Error 1
make[1]: *** [/c/DESARROLLO/ESP32/esp-idf/make/project.mk:468: component-esp_http_client-build] Error 2

--- Build failed
--- Press Ctrl+] to exit monitor.
--- Press Ctrl+F to build & flash project.
--- Press Ctrl+A to build & flash app.
--- Press any other key to resume monitor (resets target).

[jitin17]

@lrodenasSistel Oops! I didn't take a notice of your IDF version. My bad. I thought the problem is due to the latest changes on master branch. We'll get back to you soon.

[jitin17]

@lrodenasSistel After our evaluation, we think if a esp_http_client_perform fails in synchronous mode then it is expected to call esp_http_client_close() API. And if you don't want to do so since it will invoke SSL handshake again then you can use the asynchronous mode of esp_http_client_perform. As of now, asynchronous mode is supported only on the master branch and will be a part of the next stable release.

[jitin17]

@lrodenasSistel Can we close this issue?

[lrodenasSistel]

Is the "asynchronous mode of esp_http_client_perform" already part of stable release so we can test it? From what version?
Is this statement "we think if a esp_http_client_perform fails in synchronous mode then it is expected to call esp_http_client_close() API" still valid? If so, is it written on documentation anywhere for future users?

Thank you

[jitin17]

@lrodenasSistel

Is the "asynchronous mode of esp_http_client_perform" already part of stable release so we can test it? From what version?

It is a part of stable release v3.2 and so on. You can use it the way it is shown here

Is this statement "we think if a esp_http_client_perform fails in synchronous mode then it is expected to call esp_http_client_close() API" still valid? If so, is it written on documentation anywhere for future users?

Sorry, I don't think it is mentioned in the document. I'll try to add it to the documentation of esp_http_client_perform() API . Thanks!!

[shubhamkulkarni97]

@lrodenasSistel Do you have any updates on this issue?

[RoderickJDunn]

This issue still exists in v4.1-dev-1931-g68be5f6ca, and calling esp_http_client_close fixes the problem. I also couldn't find this anywhere in the documentation.

Do we need to call esp_http_client_close for _all_ errors returned from esp_http_client_perform?

[shubhamkulkarni97]

@RoderickJDunn, I was not able to reproduce the issue. Please check logs attached below:

I (10574) HTTP_CLIENT: HTTP GET Status = 200, content_length = 270
E (11084) HTTP_CLIENT: HTTP POST request failed: ESP_ERR_HTTP_FETCH_HEADER
I (11394) HTTP_CLIENT: HTTP PUT Status = 200, content_length = 444
I (11804) HTTP_CLIENT: HTTP PATCH Status = 200, content_length = 335
I (12214) HTTP_CLIENT: HTTP DELETE Status = 200, content_length = 336
I (12624) HTTP_CLIENT: HTTP HEAD Status = 200, content_length = 270
I (12624) HTTP_CLIENT: HTTP_EVENT_DISCONNECTED

Did you face this issue when running esp_http_client example or while running custom code?
Can you share steps to reproduce the issue? Also, can you share logs when issue occurs?

[chegewara]

I got the same issue in release/v3.3, but closing connection didnt solve my problem. I found that adding this code before perform solved it, so i think it may be some timing issue or something:
esp_http_client_open(client, 0);
Thats correct, open connection with 0 length payload. Now i dont get ESP_ERR_HTTP_FETCH_HEADER anymore and all connections seems to be successful on first try.

[AxelLin]

I also observed the ESP_ERR_HTTP_FETCH_HEADER in v4.3-dev-771-gc77c4ccf6c43.
The esp_http_client_fetch_headers -> esp_transport_read returns -1.
(It happens on both http and https)

[KaeLL]

I can confirm this problem affects v4.1 as well, exactly like @AxelLin described.

[shubhamkulkarni97]

Hi @AxelLin @KaeLL, Can you please provide sample code with sdkconfig to reproduce this issue? Currently I'm not able to reproduce the issue.

[weizhen1883]

does anyone have the solution to this problem?

[KaeLL]

Hi @AxelLin @KaeLL, Can you please provide sample code with sdkconfig to reproduce this issue? Currently I'm not able to reproduce the issue.

Unfortunately no. I don't know exactly what's causing esp_transport_read to return -1, and currently I'm a little to busy to dedicate time to find out.

[dakriy]

Hi @AxelLin @KaeLL, Can you please provide sample code with sdkconfig to reproduce this issue? Currently I'm not able to reproduce the issue.

I was able to reproduce this issue by waiting around 60-70 seconds between requests using the same client.

[shubhamkulkarni97]

@AxelLin @KaeLL @weizhen1883 @dakriy Sorry for long delay.

I was able to reproduce this issue by waiting around 60-70 seconds between requests(when httpbin.org is used as server) however ESP_ERR_HTTP_FETCH_HEADER error occurs within 10 seconds when using AWS S3 as server.

This happens because idle time is set for each server, after which inactive/idle connection with will be closed. ESP_ERR_HTTP_FETCH_HEADER error occurs as server has closed the connection.

You can check enabling Socket debug messages in menuconfig (under Component Config > LWIP > Debug) and setting LWIP_DEBUG to LWIP_DBG_ON (in lwipopts.h).
Following debug messages are printed:

lwip_select(55, 0x3ffc9288, 0x0, 0x3ffc9290, tvsec=5 tvusec=0)
lwip_selscan: fd=54 ready for reading
lwip_select: nready=1
lwip_recvfrom(54, 0x3ffc9fe8, 5, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=-15, pbuf=0x0
lwip_recv_tcp: p == NULL, error is "Connection closed."!
lwip_recvfrom(54):  addr=52.217.18.44 port=443 len=0
E (17265) HTTP_CLIENT: Error perform http request ESP_ERR_HTTP_FETCH_HEADER

These messages show Connection closed error.

Idle time will vary from server to server. Hence, it is not recommended to keep connection open for a long time and reuse the same.

(CC: @mahavirj)

[Alvin1Zhang]

Thanks for reporting, feel free to reopen.