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

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);
}