lwip_recv_tcp Invalid Copylen Error during File Upload in Async HTTP Web Server (IDFGH-12039)

Luca96 commented 8 months 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.

v5.2-beta1

Espressif SoC revision.

ESP32-D0WD-V3 (revision v3.1)

Operating System used.

Windows

How did you build your project?

VS Code IDE

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

CMD

Development Kit.

ESP32-WROOM-32

Power Supply used.

USB

What is the expected behavior?

The expected behavior is to handle file upload requests by the server, asynchronously. The httpd_req_recv function should receive a chunk of bytes without failing, such that the received bytes can be then written on an SD card. The whole thing handled by FreeRTOS's tasks.

What is the actual behavior?

When the task is invoked by the FreeRTOS sheduler, the file upload handler manages to receive a few chunks but then crashes suddenly, apparently at random points during the upload. The error I get is:

assert failed: lwip_recv_tcp /IDF/components/lwip/lwip/src/api/sockets.c:1001 (invalid copylen)

and is triggered by the httpd_req_recv function.

Steps to reproduce.

Basically my code merges the async_handlers example with the file_serving one. The example code is:

#include <stdio.h>
#include <string.h>
#include <sys/param.h>
#include <errno.h>

#include "freertos/FreeRTOS.h"
#include "freertos/semphr.h"
#include <esp_wifi.h>
#include <esp_event.h>
#include <esp_log.h>
#include <esp_system.h>
#include <nvs_flash.h>
#include <sys/param.h>
#include "nvs_flash.h"
#include "esp_netif.h"
#include "esp_eth.h"
#include "esp_tls_crypto.h"
#include <esp_http_server.h>

#include "wifi_ap.h"

#define ASYNC_WORKER_TASK_PRIORITY      5
#define ASYNC_WORKER_TASK_STACK_SIZE    2048

static const char *TAG = "example";

// Async reqeusts are queued here while they wait to
// be processed by the workers
static QueueHandle_t async_req_queue;

// Track the number of free workers at any given time
static SemaphoreHandle_t worker_ready_count;

// Each worker has its own thread
static TaskHandle_t worker_handles[CONFIG_EXAMPLE_MAX_ASYNC_REQUESTS];

typedef esp_err_t (*httpd_req_handler_t)(httpd_req_t *req);

typedef struct {
    httpd_req_t* req;
    httpd_req_handler_t handler;
} httpd_async_req_t;

static bool is_on_async_worker_thread(void)
{
    // is our handle one of the known async handles?
    TaskHandle_t handle = xTaskGetCurrentTaskHandle();
    for (int i = 0; i < CONFIG_EXAMPLE_MAX_ASYNC_REQUESTS; i++) {
        if (worker_handles[i] == handle) {
            return true;
        }
    }
    return false;
}

// Submit an HTTP req to the async worker queue
static esp_err_t submit_async_req(httpd_req_t *req, httpd_req_handler_t handler)
{
    // must create a copy of the request that we own
    httpd_req_t* copy = NULL;
    esp_err_t err = httpd_req_async_handler_begin(req, &copy);
    if (err != ESP_OK) {
        return err;
    }

    httpd_async_req_t async_req = {
        .req = copy,
        .handler = handler,
    };

    // How should we handle resource exhaustion?
    // In this example, we immediately respond with an
    // http error if no workers are available.
    int ticks = 0;

    // counting semaphore: if success, we know 1 or
    // more asyncReqTaskWorkers are available.
    if (xSemaphoreTake(worker_ready_count, ticks) == false) {
        ESP_LOGE(TAG, "No workers are available");
        httpd_req_async_handler_complete(copy); // cleanup
        return ESP_FAIL;
    }

    // Since worker_ready_count > 0 the queue should already have space.
    // But lets wait up to 100ms just to be safe.
    if (xQueueSend(async_req_queue, &async_req, pdMS_TO_TICKS(100)) == false) {
        ESP_LOGE(TAG, "worker queue is full");
        httpd_req_async_handler_complete(copy); // cleanup
        return ESP_FAIL;
    }

    return ESP_OK;
}

static void async_req_worker_task(void *p)
{
    ESP_LOGI(TAG, "starting async req task worker");

    while (true) {
        // counting semaphore - this signals that a worker
        // is ready to accept work
        xSemaphoreGive(worker_ready_count);

        // wait for a request
        httpd_async_req_t async_req;
        if (xQueueReceive(async_req_queue, &async_req, portMAX_DELAY)) {

            ESP_LOGI(TAG, "invoking %s", async_req.req->uri);

            // call the handler
            async_req.handler(async_req.req);

            // Inform the server that it can purge the socket used for
            // this request, if needed.
            if (httpd_req_async_handler_complete(async_req.req) != ESP_OK) {
                ESP_LOGE(TAG, "failed to complete async req");
            }
        }
    }

    ESP_LOGW(TAG, "worker stopped");
    vTaskDelete(NULL);
}

static void start_async_req_workers(void)
{
    // counting semaphore keeps track of available workers
    worker_ready_count = xSemaphoreCreateCounting(
        CONFIG_EXAMPLE_MAX_ASYNC_REQUESTS,  // Max Count
        0); // Initial Count
    if (worker_ready_count == NULL) {
        ESP_LOGE(TAG, "Failed to create workers counting Semaphore");
        return;
    }

    // create queue
    async_req_queue = xQueueCreate(1, sizeof(httpd_async_req_t));
    if (async_req_queue == NULL){
        ESP_LOGE(TAG, "Failed to create async_req_queue");
        vSemaphoreDelete(worker_ready_count);
        return;
    }

    // start worker tasks
    for (int i = 0; i < CONFIG_EXAMPLE_MAX_ASYNC_REQUESTS; i++) {

        bool success = xTaskCreate(async_req_worker_task, "async_req_worker",
                                    ASYNC_WORKER_TASK_STACK_SIZE, // stack size
                                    (void *)0, // argument
                                    ASYNC_WORKER_TASK_PRIORITY, // priority
                                    &worker_handles[i]);

        if (!success) {
            ESP_LOGE(TAG, "Failed to start asyncReqWorker");
            continue;
        }
    }
}

static esp_err_t index_handler(httpd_req_t *req)
{
    ESP_LOGI(TAG, "uri: /");

    extern const unsigned char upload_script_start[] asm("_binary_page_html_start");
    extern const unsigned char upload_script_end[]   asm("_binary_page_html_end");
    const size_t upload_script_size = (upload_script_end - upload_script_start);

    httpd_resp_send_chunk(req, (const char *) upload_script_start, upload_script_size);
    httpd_resp_sendstr_chunk(req, NULL);
    return ESP_OK;
}

// --------------------------------------------------------------------------------------
// -- FILE UPLOAD
// --------------------------------------------------------------------------------------
#define SCRATCH_BUFSIZE  8192

struct file_server_data {
    /* Base path of file storage */
    char base_path[256];

    /* Scratch buffer for temporary storage during file transfer */
    char scratch[SCRATCH_BUFSIZE];
};

static esp_err_t upload_post_handler(httpd_req_t *req)
{
    ESP_LOGI(TAG, "Receiving file");
    ESP_LOGI(TAG, "uri: /upload/file, socket: %d", httpd_req_to_sockfd(req));

    /* Retrieve the pointer to scratch buffer for temporary storage */
    char *buf = ((struct file_server_data *)req->user_ctx)->scratch;
    int received;

    /* Content length of the request gives
     * the size of the file being uploaded */
    int remaining = req->content_len;

    while (remaining > 0) {
        ESP_LOGI(TAG, "Remaining size : %d", remaining);

        /* Receive the file part by part into a buffer */
        if ((received = httpd_req_recv(req, buf, MIN(remaining, SCRATCH_BUFSIZE))) <= 0) {
            if (received == HTTPD_SOCK_ERR_TIMEOUT) {
                /* Retry if timeout occurred */
                continue;
            }

            ESP_LOGE(TAG, "File reception failed! %s", strerror(errno));

            /* Respond with 500 Internal Server Error */
            httpd_resp_send_err(req, HTTPD_500_INTERNAL_SERVER_ERROR, "Failed to receive file");
            return ESP_FAIL;
        }

        /* Keep track of remaining size of
         * the file left to be uploaded */
        remaining -= received;
    }

    /* Close file upon upload completion */
    ESP_LOGI(TAG, "File reception complete");

    /* Redirect onto root to see the updated file list */
    httpd_resp_set_status(req, "303 See Other");
    httpd_resp_set_hdr(req, "Location", "/");
    httpd_resp_sendstr(req, "File uploaded successfully");

    return ESP_OK;
}

static esp_err_t async_upload_handler(httpd_req_t *req)
{
    ESP_LOGI(TAG, "uri: /upload, socket: %d", httpd_req_to_sockfd(req));

    // This handler is first invoked on the httpd thread.
    // In order to free the httpd thread to handle other requests,
    // we must resubmit our request to be handled on an async worker thread.
    if (is_on_async_worker_thread() == false) {
        // submit
        if (submit_async_req(req, upload_post_handler) == ESP_OK) {
            return ESP_OK;
        } else {
            httpd_resp_set_status(req, "503 Busy");
            httpd_resp_sendstr(req, "<div> no workers available. server busy.</div>");
            return ESP_OK;
        }
    }

    return upload_post_handler(req);
}

// --------------------------------------------------------------------------------------
// -- WEB SERVER
// --------------------------------------------------------------------------------------

static httpd_handle_t start_webserver(void)
{
    httpd_handle_t server = NULL;
    httpd_config_t config = HTTPD_DEFAULT_CONFIG();
    config.lru_purge_enable = true;

    // It is advisable that httpd_config_t->max_open_sockets > MAX_ASYNC_REQUESTS
    // Why? This leaves at least one socket still available to handle
    // quick synchronous requests. Otherwise, all the sockets will
    // get taken by the long async handlers, and your server will no
    // longer be responsive.
    config.max_open_sockets = CONFIG_EXAMPLE_MAX_ASYNC_REQUESTS + 1;
    config.uri_match_fn = httpd_uri_match_wildcard;

    static struct file_server_data *server_data = NULL;
    server_data = calloc(1, sizeof(struct file_server_data));
    if (!server_data) {
        ESP_LOGE(TAG, "Failed to allocate memory for server data");
        return ESP_ERR_NO_MEM;
    }

    // Start the httpd server
    ESP_LOGI(TAG, "Starting server on port: '%d'", config.server_port);
    if (httpd_start(&server, &config) != ESP_OK) {
        ESP_LOGI(TAG, "Error starting server!");
        return NULL;
    }

    const httpd_uri_t index_uri = {
        .uri       = "/",
        .method    = HTTP_GET,
        .handler   = index_handler,
    };

    /* URI handler for uploading files to server */
    httpd_uri_t file_upload = {
        .uri       = "/upload/*",   // Match all URIs of type /upload/path/to/file
        .method    = HTTP_POST,
        .handler   = async_upload_handler,
        .user_ctx  = server_data    // Pass server data as context
    };

    // Set URI handlers
    ESP_LOGI(TAG, "Registering URI handlers");
    httpd_register_uri_handler(server, &index_uri);
    httpd_register_uri_handler(server, &file_upload);

    return server;
}

void app_main(void)
{
    static httpd_handle_t server = NULL;

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

    /* Initialize Wi-Fi Access Point */
    wifi_init_softap();

    // start workers
    start_async_req_workers();

    /* Start the server for the first time */
    server = start_webserver();
}

The web server's index HTML page is (which is embedded by CMake):

<html>
    <body>
        <script>
            function upload() {
                var upload_path = "/upload/file.png";
                var file = document.getElementById("newfile").files[0];
                var xhttp = new XMLHttpRequest();
                xhttp.onreadystatechange = function() {
                    if (xhttp.readyState == 4) {
                        if (xhttp.status == 200) {
                            document.open();
                            document.write(xhttp.responseText);
                            document.close();
                        } else if (xhttp.status == 0) {
                            alert("Server closed the connection abruptly!");
                            location.reload()
                        } else {
                            alert(xhttp.status + " Error!\n" + xhttp.responseText);
                            location.reload()
                        }
                    }
                };

                console.log("sendind file of size: " + file.size.toString());

                xhttp.open("POST", upload_path, true);
                xhttp.send(file);
            }
        </script>
        <!-- UPLOAD FORM -->
        <input id="newfile" type="file" wfd-id="id0">
        <button id="upload" type="button" onclick="upload()">Upload</button>
    </body>
</html>

Moreover, I use the ESP32 as a Wi-Fi AP from which I connect to it with my laptop and open the web server at the given IP address: in my case is 192.16.4.1.

The code for the Soft AP (wifi_ap.h) is:

#include <string.h>

#include "esp_err.h"
#include "esp_log.h"
#include "esp_wifi.h"
#include "esp_event.h"
#include "esp_mac.h"

// ------------------------------------------------------------------------------------------------
// -- WIFI ACCESS POINT
// ------------------------------------------------------------------------------------------------
static const char *WIFI_TAG = "WIFI AP";

static void wifi_event_handler(void* arg, esp_event_base_t event_base,
                                    int32_t event_id, void* event_data) {
    if (event_id == WIFI_EVENT_AP_STACONNECTED) {
        wifi_event_ap_staconnected_t* event = (wifi_event_ap_staconnected_t*) event_data;
        ESP_LOGI(WIFI_TAG, "station "MACSTR" join, AID=%d",
                 MAC2STR(event->mac), event->aid);

    } else if (event_id == WIFI_EVENT_AP_STADISCONNECTED) {
        wifi_event_ap_stadisconnected_t* event = (wifi_event_ap_stadisconnected_t*) event_data;
        ESP_LOGI(WIFI_TAG, "station "MACSTR" leave, AID=%d",
                 MAC2STR(event->mac), event->aid);
    }
}

void wifi_init_softap(void) {
    esp_netif_create_default_wifi_ap();

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

    ESP_ERROR_CHECK(esp_event_handler_instance_register(WIFI_EVENT,
                                                        ESP_EVENT_ANY_ID,
                                                        &wifi_event_handler,
                                                        NULL,
                                                        NULL));
    wifi_config_t wifi_config = {
        .ap = {
            .ssid = CONFIG_ESP_WIFI_SSID,
            .ssid_len = strlen(CONFIG_ESP_WIFI_SSID),
            .channel = CONFIG_ESP_WIFI_CHANNEL,
            .password = CONFIG_ESP_WIFI_PASSWORD,
            .max_connection = CONFIG_ESP_MAX_STA_CONN,
#ifdef CONFIG_ESP_WIFI_SOFTAP_SAE_SUPPORT
            .authmode = WIFI_AUTH_WPA3_PSK,
            .sae_pwe_h2e = WPA3_SAE_PWE_BOTH,
#else /* CONFIG_ESP_WIFI_SOFTAP_SAE_SUPPORT */
            .authmode = WIFI_AUTH_WPA2_PSK,
#endif
            .pmf_cfg = {
                    .required = true,
            },
        },
    };

    if (strlen(CONFIG_ESP_WIFI_PASSWORD) == 0) {
        wifi_config.ap.authmode = WIFI_AUTH_OPEN;
    }

    ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_AP));
    ESP_ERROR_CHECK(esp_wifi_set_config(WIFI_IF_AP, &wifi_config));
    ESP_ERROR_CHECK(esp_wifi_start());

    ESP_LOGI(WIFI_TAG, "wifi_init_softap finished. SSID: '%s' password: '%s' channel: %d",
             CONFIG_ESP_WIFI_SSID, CONFIG_ESP_WIFI_PASSWORD, CONFIG_ESP_WIFI_CHANNEL);
}

Debug Logs.

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:7140
load:0x40078000,len:15500
load:0x40080400,len:4
0x40080400: _init at ??:?

load:0x40080404,len:3904
entry 0x40080640
I (29) boot: ESP-IDF v5.2-beta1-dirty 2nd stage bootloader
I (29) boot: compile time Feb  2 2024 21:51:38
I (30) boot: Multicore bootloader
I (34) boot: chip revision: v3.1
I (38) boot.esp32: SPI Speed      : 40MHz
I (43) boot.esp32: SPI Mode       : DIO
I (47) boot.esp32: SPI Flash Size : 2MB
I (52) boot: Enabling RNG early entropy source...
I (57) boot: Partition Table:
I (61) boot: ## Label            Usage          Type ST Offset   Length
I (68) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (76) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (83) boot:  2 factory          factory app      00 00 00010000 00100000
I (91) boot: End of partition table
I (95) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=2509ch (151708) map
I (155) esp_image: segment 1: paddr=000350c4 vaddr=3ffb0000 size=03b6ch ( 15212) load
I (161) esp_image: segment 2: paddr=00038c38 vaddr=40080000 size=073e0h ( 29664) load
I (173) esp_image: segment 3: paddr=00040020 vaddr=400d0020 size=89eb0h (564912) map
I (367) esp_image: segment 4: paddr=000c9ed8 vaddr=400873e0 size=0f224h ( 61988) load
I (403) boot: Loaded app from partition at offset 0x10000
I (403) boot: Disabling RNG early entropy source...
I (414) cpu_start: Multicore app
I (423) cpu_start: Pro cpu start user code
I (423) cpu_start: cpu freq: 160000000 Hz
I (423) cpu_start: Application information:
I (426) cpu_start: Project name:     simple
I (431) cpu_start: App version:      v5.2-beta1-dirty
I (437) cpu_start: Compile time:     Feb  2 2024 21:50:05
I (443) cpu_start: ELF file SHA256:  2dd81e2ab27c9279...
I (449) cpu_start: ESP-IDF:          v5.2-beta1-dirty
I (454) cpu_start: Min chip rev:     v0.0
I (459) cpu_start: Max chip rev:     v3.99
I (464) cpu_start: Chip rev:         v3.1
I (469) heap_init: Initializing. RAM available for dynamic allocation:
I (476) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (482) heap_init: At 3FFB7CA8 len 00028358 (160 KiB): DRAM
I (488) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (495) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (501) heap_init: At 40096604 len 000099FC (38 KiB): IRAM
I (509) spi_flash: detected chip: generic
I (512) spi_flash: flash io: dio
W (516) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (530) main_task: Started on CPU0
I (540) main_task: Calling app_main()
I (580) wifi:wifi driver task: 3ffbfbe4, prio:23, stack:6656, core=0
I (590) wifi:wifi firmware version: 639ccf2
I (590) wifi:wifi certification version: v7.0
I (590) wifi:config NVS flash: enabled
I (590) wifi:config nano formating: disabled
I (590) wifi:Init data frame dynamic rx buffer num: 32
I (600) wifi:Init static rx mgmt buffer num: 5
I (600) wifi:Init management short buffer num: 32
I (610) wifi:Init dynamic tx buffer num: 32
I (610) wifi:Init static rx buffer size: 1600
I (610) wifi:Init static rx buffer num: 10
I (620) wifi:Init dynamic rx buffer num: 32
I (620) wifi_init: rx ba win: 6
I (620) wifi_init: tcpip mbox: 32
I (630) wifi_init: udp mbox: 6
I (630) wifi_init: tcp mbox: 6
I (640) wifi_init: tcp tx win: 5744
I (640) wifi_init: tcp rx win: 5744
I (640) wifi_init: tcp mss: 1440
I (650) wifi_init: WiFi IRAM OP enabled
I (650) wifi_init: WiFi RX IRAM OP enabled
I (660) phy_init: phy_version 4780,16b31a7,Sep 22 2023,20:42:16
I (750) wifi:mode : softAP (08:d1:f9:cd:38:11)
I (750) wifi:Total power save buffer number: 16
I (750) wifi:Init max length of beacon: 752/752
I (750) wifi:Init max length of beacon: 752/752
I (760) WIFI AP: wifi_init_softap finished. SSID: 'esp32' password: '' channel: 3
I (760) esp_netif_lwip: DHCP server started on interface WIFI_AP_DEF with IP: 192.168.4.1
I (780) example: starting async req task worker
I (780) example: starting async req task worker
I (790) example: Starting server on port: '80'
I (790) example: Registering URI handlers
I (800) main_task: Returned from app_main()
I (42630) WIFI AP: station a6:2c:f9:04:68:78 join, AID=1
I (42680) esp_netif_lwip: DHCP server assigned IP to a client, IP is: 192.168.4.2
I (42730) wifi:<ba-add>idx:2 (ifx:1, a6:2c:f9:04:68:78), tid:0, ssn:27, winSize:64
I (47800) example: uri: /upload, socket: 57
I (47800) example: invoking /upload/file.png
I (47800) example: Receiving file
I (47800) example: uri: /upload/file, socket: 57
I (47810) example: Remaining size : 84337
I (47810) example: Remaining size : 81841
I (47820) example: Remaining size : 76337
I (47820) example: Remaining size : 72049
I (47830) example: Remaining size : 70609
I (47830) example: Remaining size : 69457

assert failed: lwip_recv_tcp /IDF/components/lwip/lwip/src/api/sockets.c:1001 (invalid copylen)

Backtrace: 0x400817c2:0x3ffc6d10 0x40089041:0x3ffc6d30 0x4009097d:0x3ffc6d50 0x4010fdd6:0x3ffc6e70 0x40110c33:0x3ffc6eb0 0x40110d02:0x3ffc6f10 0x400e045c:0x3ffc6f30 0x400dfdba:0x3ffc6f50 0x400dfdea:0x3ffc6f70 0x400e035c:0x3ffc6f90 0x400d683a:0x3ffc6fc0 0x400d655b:0x3ffc6fe0 0x40089b4d:0x3ffc7010
0x400817c2: panic_abort at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/esp_system/panic.c:472
0x40089041: esp_system_abort at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/esp_system/port/esp_system_chip.c:93
0x4009097d: __assert_func at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/newlib/assert.c:81
0x4010fdd6: lwip_recv_tcp at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/lwip/lwip/src/api/sockets.c:1001 (discriminator 1)
0x40110c33: lwip_recvfrom at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/lwip/lwip/src/api/sockets.c:1218
0x40110d02: lwip_recv at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/lwip/lwip/src/api/sockets.c:1283
0x400e045c: recv at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/lwip/include/lwip/sockets.h:38
 (inlined by) httpd_default_recv at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/esp_http_server/src/httpd_txrx.c:660
0x400dfdba: httpd_recv_with_opt at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/esp_http_server/src/httpd_txrx.c:121
0x400dfdea: httpd_recv at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/esp_http_server/src/httpd_txrx.c:142
0x400e035c: httpd_req_recv at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/esp_http_server/src/httpd_txrx.c:542
0x400d683a: upload_post_handler at C:/Espressif/frameworks/esp-idf-v5.2-beta1/examples/protocols/http_server/async_handlers/main/main.c:286
0x400d655b: async_req_worker_task at C:/Espressif/frameworks/esp-idf-v5.2-beta1/examples/protocols/http_server/async_handlers/main/main.c:181
0x40089b4d: vPortTaskWrapper at C:/Espressif/frameworks/esp-idf-v5.2-beta1/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134

More Information.

From the menuconfig:

CONFIG_EXAMPLE_MAX_ASYNC_REQUESTS=2.

My CMakeLists.txt is:

idf_component_register(SRCS "main.c" "wifi_ap.c"
                       EMBED_FILES "page.html" 
                       INCLUDE_DIRS "." "include")

I also say that the whole code works fine without the async part, i.e., without using the FreeRTOS's tasks.

hmalpani commented 7 months ago

Hello @Luca96 It seems like the issue is because the stack size is small for the async handler task: #define ASYNC_WORKER_TASK_STACK_SIZE 2048 Can you try increasing the stack size and test it again. Please let me know if it helps.

Thanks!

Luca96 commented 7 months ago

Hi @hmalpani , thanks for the help but increasing the task stack size still not works: I increased it to 16k but now I get a different error:

I (111177) file_server: invoking /upload/file.png
I (111187) file_server: Receiving file : /file.png...
I (111187) file_server: Remaining size : 16221
I (111207) file_server: Remaining size : 11517
I (111227) file_server: Remaining size : 6973
I (111237) file_server: Remaining size : 4480

W (116227) httpd_txrx: httpd_sock_err: error in recv : 11
W (116227) httpd_txrx: httpd_sock_err: error in recv : 128
E (116297) file_server: File reception failed! Error type: -1 (Socket is not connected)
W (116307) httpd_txrx: httpd_resp_send_err: error calling setsockopt : 9
W (116317) httpd_txrx: httpd_sock_err: error in send : 9

which is about the underlying socket being disconnected.

I've also noticed that the async task fails, then it gets resubmitted but fails again. Moreover, I tried to upload another file, getting the usual error:

assert failed: lwip_recv_tcp /IDF/components/lwip/lwip/src/api/sockets.c:1001 (invalid copylen)

Should I change the HTTP server config too? Like the core_id, task_priority and stack_size? Thanks

kayzen9 commented 6 months ago

@chipweinberger maybe you know . ..

chipweinberger commented 6 months ago

not sure of a reason.

seems lwip related

AxelLin commented 4 months ago

Try enable LWIP_DEBUG to check the values of p->tot_len, recv_left, recvd and copylen before the assertion.

david-cermak commented 1 week ago

I was able to reproduce the reported problems and confirm that there's a race condition in LWIP.

Thanks @Luca96 for sharing all these details and steps to reproduce it. Apologies for not handling this sooner, looks like a pretty nasty bug in lwip (socket owned cached pbuf not protected):

https://github.com/espressif/esp-lwip/blob/a45be9e438f6cf9c54ec150581819c3b95d5af6b/src/api/sockets.c#L1001

It was failing on v5.2, but working on the latest IDF, yet probably just because of the way worker threads are run in the latest http server.

I'm not sure how to fix the issue correctly at the moment, but will come up with some workaround at least in the following days.

espressif / esp-idf