Async HTTP client fails after downloading 15709 bytes (IDFGH-11191)

smadurange commented 1 year ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

5.1.1

Espressif SoC revision.

ESP32-D0WD-V3 (revision v3.1)

Operating System used.

Windows

How did you build your project?

Command line with Make

If you are using Windows, please specify command line type.

None

Development Kit.

ESP32 ESP-WROOM-32

Power Supply used.

USB

What is the expected behavior?

The HTTP client should download and read 48000 bytes into the buffer.

What is the actual behavior?

When is_async is set to true, the download always stops after 15709 bytes with the error transport_base: esp_tls_conn_read error, errno=No more processes. I tried increasing the timeout to a very large number (500000 ms), but the result is the same.

Steps to reproduce.

main.c:

#include <freertos/FreeRTOS.h>
#include <freertos/event_groups.h>
#include <freertos/task.h>
#include <freertos/queue.h>

#include <esp_log.h>
#include <esp_netif.h>
#include <esp_system.h>
#include <esp_wifi.h>
#include <esp_tls.h>
#include <esp_http_client.h>

#include <nvs_flash.h>
#include <sys/param.h>
#include <driver/gpio.h>

#define MAXLEN 48000

#define WIFI_SSID       CONFIG_ESP_WIFI_SSID
#define WIFI_PASSWORD   CONFIG_ESP_WIFI_PASSWORD
#define WIFI_MAX_RETRY  CONFIG_ESP_MAXIMUM_RETRY

#define WIFI_CONNECTED_BIT  BIT0
#define WIFI_ERROR_BIT      BIT1

extern const char git_srht_cert_pem_start[] asm("_binary_git_srht_cert_pem_start");
extern const char git_srht_cert_pem_end[]   asm("_binary_git_srht_cert_pem_end");

static const char* TAG = "app";

static esp_http_client_handle_t http_client;

static esp_err_t http_evt_handler(esp_http_client_event_t *evt)
{
    static int read_len;

    switch(evt->event_id) {
        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:
            int copy_len = 0;
            if (evt->user_data) {
                copy_len = MIN(evt->data_len, (MAXLEN - read_len));
                if (copy_len) {
                    memcpy(evt->user_data + read_len, evt->data, copy_len);
                    read_len += copy_len;
                }
                ESP_LOGI(TAG, "HTTP response size = %d bytes", read_len);
            }
            break;
        case HTTP_EVENT_ON_FINISH:
            ESP_LOGI(TAG, "HTTP_EVENT_ON_FINISH");
            read_len = 0;
            break;
        case HTTP_EVENT_DISCONNECTED:
            ESP_LOGI(TAG, "HTTP_EVENT_DISCONNECTED");
            int mbedtls_err = 0;
            esp_err_t err = esp_tls_get_and_clear_last_error((esp_tls_error_handle_t) evt->data,
                                                             &mbedtls_err,
                                                             NULL);
            if (err != 0) {
                ESP_LOGE(TAG, "Last esp error code: 0x%x", err);
                ESP_LOGI(TAG, "Last mbedtls failure: 0x%x", mbedtls_err);
            }
            read_len = 0;
            break;
        default:
            break;
    }
    return ESP_OK;
}

static int wifi_retry_num = 0;
static EventGroupHandle_t wifi_evt_group;

static void wifi_evt_handler(void *arg, esp_event_base_t eb, int32_t id, void *data)
{
    if (eb == WIFI_EVENT && id == WIFI_EVENT_STA_DISCONNECTED) {
        if (wifi_retry_num < WIFI_MAX_RETRY) {
            esp_wifi_connect();
            wifi_retry_num++;
            ESP_LOGI(TAG, "trying to connect to AP...");
        } else {
            ESP_LOGE(TAG,"connection to AP failed");
            xEventGroupSetBits(wifi_evt_group, WIFI_ERROR_BIT);
        }
    } else if (eb == IP_EVENT && id == IP_EVENT_STA_GOT_IP) {
        ip_event_got_ip_t* evt = (ip_event_got_ip_t*) data;
        ESP_LOGI(TAG, "connected to AP with ip:" IPSTR, IP2STR(&evt->ip_info.ip));
        wifi_retry_num = 0;
        xEventGroupSetBits(wifi_evt_group, WIFI_CONNECTED_BIT);
    }
}

static inline void wifi_connect(void)
{
    wifi_evt_group = xEventGroupCreate();
    esp_netif_create_default_wifi_sta();

    wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
    ESP_ERROR_CHECK(esp_wifi_init(&cfg));

    esp_event_handler_instance_t any_id;
    ESP_ERROR_CHECK(esp_event_handler_instance_register(WIFI_EVENT,
                                                        ESP_EVENT_ANY_ID,
                                                        &wifi_evt_handler,
                                                        NULL,
                                                        &any_id));

    esp_event_handler_instance_t got_ip;
    ESP_ERROR_CHECK(esp_event_handler_instance_register(IP_EVENT,
                                                        IP_EVENT_STA_GOT_IP,
                                                        &wifi_evt_handler,
                                                        NULL,
                                                        &got_ip));

    wifi_config_t wifi_config = {
        .sta = {
            .ssid = WIFI_SSID,
            .password = WIFI_PASSWORD,
            .threshold.authmode = WIFI_AUTH_WPA2_PSK
        },
    };

    ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_STA));
    ESP_ERROR_CHECK(esp_wifi_set_config(WIFI_IF_STA, &wifi_config) );

    ESP_ERROR_CHECK(esp_wifi_start());
    ESP_ERROR_CHECK(esp_wifi_connect());

    xEventGroupWaitBits(wifi_evt_group,
                        WIFI_CONNECTED_BIT | WIFI_ERROR_BIT,
                        pdFALSE,
                        pdFALSE,
                        portMAX_DELAY);

    ESP_LOGI(TAG, "wifi station initialized");
}

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

    ESP_ERROR_CHECK(esp_event_loop_create_default());
    ESP_ERROR_CHECK(esp_netif_init());

    wifi_connect();

    uint8_t *buf = malloc(sizeof(buf[0]) * MAXLEN);

    esp_http_client_config_t config = {
        .url = "https://git.sr.ht/~sadeep/epd-test-docs/blob/master/doc-1.ebm",
        .is_async = true,
        .timeout_ms = 5000,
        .user_data = buf,
        .event_handler = http_evt_handler,
        .cert_pem = git_srht_cert_pem_start
    };

    http_client = esp_http_client_init(&config);

    for(;;) {
        rc = esp_http_client_perform(http_client);
        if (rc != ESP_ERR_HTTP_EAGAIN)
            break;
        vTaskDelay((TickType_t) 100 / portTICK_PERIOD_MS);
    }

    if (rc == ESP_OK)
        ESP_LOGI(TAG, "HTTPS Status = %d, content_length = %"PRId64,
                      esp_http_client_get_status_code(http_client),
                      esp_http_client_get_content_length(http_client));
    else
        ESP_LOGE(TAG, "page download error: %s", esp_err_to_name(rc));
}

Debug Logs.

I (7554) app: connected to AP with ip:192.168.0.7
I (7564) app: wifi station initialized
D (7564) HTTP_CLIENT: Begin connect to: https://git.sr.ht:443
D (7574) esp-tls: host:git.sr.ht: strlen 9
D (7584) esp-tls: [sock=54] Resolved IPv4 address: 173.195.146.142
D (7584) esp-tls: [sock=54] Connecting to server. HOST: git.sr.ht, Port: 443
D (7594) esp-tls: connecting...
I (7954) wifi:<ba-add>idx:1 (ifx:0, 9c:53:22:fc:16:20), tid:4, ssn:0, winSize:64
D (7974) esp-tls: handshake in progress...
D (7974) HTTP_CLIENT: Connection not yet established
D (8074) HTTP_CLIENT: Begin connect to: https://git.sr.ht:443
...
D (9634) HTTP_CLIENT: Begin connect to: https://git.sr.ht:443
D (9634) esp-tls: handshake in progress...
D (9634) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:1 posted to loop 0x3ffbb1d8
D (9634) HTTP_CLIENT: Write header[3]: GET /~sadeep/epd-test-docs/blob/master/doc-1.ebm HTTP/1.1
User-Agent: ESP32 HTTP Client/1.0
Host: git.sr.ht
Content-Length: 0
D (9654) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:2 posted to loop 0x3ffbb1d8
E (10004) transport_base: esp_tls_conn_read error, errno=No more processes
W (10004) HTTP_CLIENT: Connection timed out before data was ready!
E (10324) transport_base: esp_tls_conn_read error, errno=No more processes
W (10324) HTTP_CLIENT: Connection timed out before data was ready!
E (10584) transport_base: esp_tls_conn_read error, errno=No more processes
W (10584) HTTP_CLIENT: Connection timed out before data was ready!
D (10944) HTTP_CLIENT: on_message_begin
D (10944) HTTP_CLIENT: HEADER=Server:nginx
I (10944) app: HTTP_EVENT_ON_HEADER, key=Server, value=nginx
D (10944) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (10954) HTTP_CLIENT: HEADER=Date:Thu, 05 Oct 2023 00:04:11 GMT
I (10964) app: HTTP_EVENT_ON_HEADER, key=Date, value=Thu, 05 Oct 2023 00:04:11 GMT
D (10974) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (10984) HTTP_CLIENT: HEADER=Content-Type:application/octet-stream
I (10984) app: HTTP_EVENT_ON_HEADER, key=Content-Type, value=application/octet-stream
D (10994) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (11004) HTTP_CLIENT: HEADER=Content-Length:48000
I (11014) app: HTTP_EVENT_ON_HEADER, key=Content-Length, value=48000
D (11014) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (11024) HTTP_CLIENT: HEADER=Connection:keep-alive
I (11034) app: HTTP_EVENT_ON_HEADER, key=Connection, value=keep-alive
D (11044) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (11054) HTTP_CLIENT: HEADER=Content-Disposition:attachment; filename=doc-1.ebm
I (11054) app: HTTP_EVENT_ON_HEADER, key=Content-Disposition, value=attachment; filename=doc-1.ebm
D (11064) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (11074) HTTP_CLIENT: HEADER=Cache-Control:no-cache
I (11084) app: HTTP_EVENT_ON_HEADER, key=Cache-Control, value=no-cache
D (11094) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (11104) HTTP_CLIENT: HEADER=Content-Security-Policy:upgrade-insecure-requests; sandbox; frame-src 'none'; media-src 'none'; script-src 'none'; object-src 'none'; worker-src 'none';
I (11114) app: HTTP_EVENT_ON_HEADER, key=Content-Security-Policy, value=upgrade-insecure-requests; sandbox; frame-src 'none'; media-src 'none'; script-src 'none'; object-src 'none'; worker-src 'none';
D (11134) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (11144) HTTP_CLIENT: HEADER=X-Clacks-Overhead:GNU Terry Pratchett
I (11154) app: HTTP_EVENT_ON_HEADER, key=X-Clacks-Overhead, value=GNU Terry Pratchett
D (11164) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (11174) HTTP_CLIENT: HEADER=Strict-Transport-Security:max-age=31536000; includeSubDomains; preload
I (11174) app: HTTP_EVENT_ON_HEADER, key=Strict-Transport-Security, value=max-age=31536000; includeSubDomains; preload
D (11194) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (11204) transport_base: remain data in cache, need to read again
D (11204) HTTP_CLIENT: HEADER=Permissions-Policy:interest-cohort=()
I (11214) app: HTTP_EVENT_ON_HEADER, key=Permissions-Policy, value=interest-cohort=()
D (11224) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (11234) HTTP_CLIENT: HEADER=Content-Security-Policy:default-src 'none'; style-src 'self' 'unsafe-inline'; img-src * data:; script-src 'self' 'unsafe-inline'
I (11244) app: HTTP_EVENT_ON_HEADER, key=Content-Security-Policy, value=default-src 'none'; style-src 'self' 'unsafe-inline'; img-src * data:; script-src 'self' 'unsafe-inline'
D (11264) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:3 posted to loop 0x3ffbb1d8
D (11274) HTTP_CLIENT: http_on_headers_complete, status=200, offset=676, nread=676
D (11284) HTTP_CLIENT: http_on_body 349
I (11284) app: HTTP response size = 349 bytes
D (11284) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:4 posted to loop 0x3ffbb1d8
D (11294) HTTP_CLIENT: content_length = 48000
D (11304) HTTP_CLIENT: data_process=349, content_length=48000
D (11304) transport_base: remain data in cache, need to read again
D (11314) HTTP_CLIENT: http_on_body 512
I (11314) app: HTTP response size = 861 bytes
...
D (12204) HTTP_CLIENT: data_process=15197, content_length=48000
D (12214) transport_base: remain data in cache, need to read again
D (12224) HTTP_CLIENT: http_on_body 512
I (12224) app: HTTP response size = 15709 bytes
D (12234) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:4 posted to loop 0x3ffbb1d8
D (12244) HTTP_CLIENT: data_process=15709, content_length=48000
E (12244) transport_base: esp_tls_conn_read error, errno=No more processes
D (12354) HTTP_CLIENT: data_process=15709, content_length=48000
E (12354) transport_base: esp_tls_conn_read error, errno=No more processes
D (12454) HTTP_CLIENT: data_process=15709, content_length=48000
E (12564) transport_base: esp_tls_conn_read error, errno=No more processes
D (12664) HTTP_CLIENT: data_process=15709, content_length=48000
E (12874) transport_base: esp_tls_conn_read error, errno=No more processes
D (12974) HTTP_CLIENT: data_process=15709, content_length=48000
D (14894) transport_base: remain data in cache, need to read again
...
D (14894) HTTP_CLIENT: data_process=15709, content_length=48000
V (19914) transport_base: poll_read: select - Timeout before any socket was ready!
D (20014) HTTP_CLIENT: data_process=15709, content_length=48000
V (25024) transport_base: poll_read: select - Timeout before any socket was ready!
D (25124) HTTP_CLIENT: data_process=15709, content_length=48000
D (87554) HTTP_CLIENT: data_process=15709, content_length=48000
D (88944) HTTP_CLIENT: data_process=15709, content_length=48000
D (88944) HTTP_CLIENT: Read finish or server requests close
I (88944) app: HTTP_EVENT_ON_FINISH
D (88944) event: no handlers have been registered for event ESP_HTTP_CLIENT_EVENT:5 posted to loop 0x3ffbb1d8
I (88954) app: HTTPS Status = 200, content_length = 48000
I (88964) main_task: Returned from app_main()

More Information.

If I set is_async to false in the exact same code above, it works (downloads the full 48000-byte file).

hmalpani commented 1 year ago

Hello @smadurange Apologies for the delayed response. I have created a patch to fix this issue. Can you please try with the following patch and let me know if it solves the issue for you.

Thanks!

IDFGH_11191.txt

hmalpani commented 12 months ago

Hello @smadurange Any updates on this issue? Does the patch I shared works for you?

smadurange commented 11 months ago

@hmalpani I do not have access to the chip at the moment. I will test this next week and get back to you.

smadurange commented 11 months ago

@hmalpani I tried with the patch, now I get the full 48KB file. However, the HTTP_EVENT_ON_DATA event doesn't seem to stop firing after downloading 48KB. I continue to see the log line I (19828) app: HTTP response size = 48000 bytes. I'm guessing the rc != ESP_ERR_HTTP_EAGAIN condition doesn't evaluate to true in the following for loop in the main function:

for(;;) {
    rc = esp_http_client_perform(http_client);
    if (rc != ESP_ERR_HTTP_EAGAIN)
        break;
    vTaskDelay((TickType_t) 100 / portTICK_PERIOD_MS);
}

hmalpani commented 11 months ago

Hello @smadurange

I think the file you are downloading have size greater than 48KB. In that case, client will continue to download the file. If you want to download only 48KB, you can use partial download. Or you can handle the 48KB downloaded chunk in the event handler. Hope this helps.

smadurange commented 11 months ago

Hello @smadurange

I think the file you are downloading have size greater than 48KB. In that case, client will continue to download the file. If you want to download only 48KB, you can use partial download. Or you can handle the 48KB downloaded chunk in the event handler. Hope this helps.

Yes, you are right. Used the wrong file. So, this patch fixes my original issue. Thanks!

espressif / esp-idf