esp_http_server: Reading data from PUT request in async handler doesn't return any data (IDFGH-13053)

fgrfl commented 2 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.

5.2.1

Espressif SoC revision.

ESP32-D0WD (revision v1.0), ESP32-S3 (QFN56) (revision v0.1)

Operating System used.

Linux

How did you build your project?

Command line with idf.py

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

None

Development Kit.

Custom Board,

Power Supply used.

External 3.3V

What is the expected behavior?

I expected to receive a large file in a PUT request URI handler that runs in an asynchronous context

What is the actual behavior?

The function httpd_req_recv returns no data, but HTTPD_SOCK_ERR_TIMEOUT, even though httpd_req_t::content_len indicates there are 338476 bytes to read.

Steps to reproduce.

Use the async_handlers example

change the method of the long handler to HTTP_PUT and replace the sending part of static esp_err_t long_async_handler(httpd_req_t *req) with the following receiving code:


//vTaskDelay(pdMS_TO_TICKS(100));

int remaining = req->content_len;

while (remaining > 0) {
    int received = 0;
    char buf[500];
    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, 500))) <= 0) {
        if (received == HTTPD_SOCK_ERR_TIMEOUT) {
            /* Retry if timeout occurred */
            ESP_LOGW(TAG, "Timeout reading socket");
            continue;
        }
        ESP_LOGE(TAG, "File reception failed! Error: %d", received);
        /* Respond with 500 Internal Server Error */
        httpd_resp_send_err(req, HTTPD_500_INTERNAL_SERVER_ERROR, "Failed to receive file");
        return ESP_FAIL;
    }
    ESP_LOGI(TAG, "received %d bytes", received);
    // Simulate slow processing/writing the file somwehere
    vTaskDelay(pdMS_TO_TICKS(1000));

    remaining -= received;
}
ESP_LOGI(TAG, "File successfully received");
httpd_resp_set_status(req, HTTPD_200);
httpd_resp_sendstr(req, "File successfully received");
return ESP_OK;

3. Use this command to send a large file (multiple kB): `curl -X PUT "10.42.0.220/long" -F 'file=@file.txt`
4. You'll get slightly different results if a small delay is added before the first buffer is received

### Debug Logs.

```plain
Without any initial delay:
I (40820) example: uri: /long
I (40820) example: invoking /long
I (40820) example: uri: /long
I (40820) example: Remaining size : 16670
I (40840) example: received 500 bytes
I (41840) example: Remaining size : 16170
W (45900) httpd_txrx: httpd_sock_err: error in recv : 11
W (45900) httpd_txrx: httpd_sock_err: error in recv : 128
E (45900) example: File reception failed! Error: -1
W (45910) httpd_txrx: httpd_resp_send_err: 500 Internal Server Error - Failed to receive file
W (45910) httpd_txrx: httpd_resp_send_err: error calling setsockopt : 9
W (45920) httpd_txrx: httpd_sock_err: error in send : 9

With initial delay before receiving the first bytes:
I (34820) example: uri: /long
I (34820) example: invoking /long
I (34820) example: uri: /long
I (34920) example: Remaining size : 16670
W (39920) httpd_txrx: httpd_sock_err: error in recv : 11
W (39920) example: Timeout reading socket
I (39920) example: Remaining size : 16670
W (44930) httpd_txrx: httpd_sock_err: error in recv : 11
W (44930) example: Timeout reading socket
I (44930) example: Remaining size : 16670
W (49940) httpd_txrx: httpd_sock_err: error in recv : 11
W (49940) example: Timeout reading socket
I (49940) example: Remaining size : 16670
W (54950) httpd_txrx: httpd_sock_err: error in recv : 11
W (54950) example: Timeout reading socket
I (54950) example: Remaining size : 16670
W (59960) httpd_txrx: httpd_sock_err: error in recv : 11
...

More Information.

I tested it with IDF-5.2.1, but I have applied the patch from https://github.com/espressif/esp-idf/issues/13430

With this additional patch, it works fine, PUT requests with a large file as payload are handled correctly in the asynchronous handler and the main httpd task doesn't try to "steal" data from that socket:

diff --git a/components/esp_http_server/src/httpd_main.c b/components/esp_http_server/src/httpd_main.c
index a1006feb36..fd434e87ae 100644
--- a/components/esp_http_server/src/httpd_main.c
+++ b/components/esp_http_server/src/httpd_main.c
@@ -254,6 +254,11 @@ static int httpd_process_session(struct sock_db *session, void *context)
         return 1;
     }

+    // session is busy in an async task, do not process here.
+    if (session->for_async_req) {
+        return 1;
+    }
+
     process_session_context_t *ctx = (process_session_context_t *)context;
     int fd = session->fd;

diff --git a/components/esp_http_server/src/httpd_sess.c b/components/esp_http_server/src/httpd_sess.c
index a10c62fb1a..ac03edf8d1 100644
--- a/components/esp_http_server/src/httpd_sess.c
+++ b/components/esp_http_server/src/httpd_sess.c
@@ -72,6 +72,7 @@ static int enum_function(struct sock_db *session, void *context)
     case HTTPD_TASK_INIT:
         session->fd = -1;
         session->ctx = NULL;
+        session->for_async_req = false;
         break;
     // Get active session
     case HTTPD_TASK_GET_ACTIVE:
@@ -87,7 +88,7 @@ static int enum_function(struct sock_db *session, void *context)
         break;
     // Set descriptor
     case HTTPD_TASK_SET_DESCRIPTOR:
-        if (session->fd != -1) {
+        if (session->fd != -1 && !session->for_async_req) {
             FD_SET(session->fd, ctx->fdset);
             if (session->fd > ctx->max_fd) {
                 ctx->max_fd = session->fd;
diff --git a/components/esp_http_server/src/httpd_txrx.c b/components/esp_http_server/src/httpd_txrx.c
index ad5e8ed973..fa50378f69 100644
--- a/components/esp_http_server/src/httpd_txrx.c
+++ b/components/esp_http_server/src/httpd_txrx.c
@@ -631,9 +631,11 @@ esp_err_t httpd_req_async_handler_begin(httpd_req_t *r, httpd_req_t **out)
     }
     memcpy(async_aux->resp_hdrs, r_aux->resp_hdrs, hd->config.max_resp_headers * sizeof(struct resp_hdr));

+    // Prevent the main thread from reading the rest of the request after the handler returns.
+    r_aux->remaining_len = 0;
+
     // mark socket as "in use"
-    struct httpd_req_aux *ra = r->aux;
-    ra->sd->for_async_req = true;
+    r_aux->sd->for_async_req = true;

     *out = async;

fgrfl commented 1 month ago

Were you able to reproduce the issue? Do you want me to create a PR with the proposed patch?

hmalpani commented 1 month ago

Hello @fgrfl Thanks for raising the issue. I was able to reproduce the issue. The patch you shared seems to fix the issue as well. If you want you could create a PR or else I can create an internal MR with the fix you provided. Thanks!

fgrfl commented 1 month ago

I've signed the CLA and created a PR

wubbl0rz commented 1 month ago

same problem here with HTTP_POST. your patch fixes it. @fgrfl :+1:

espressif / esp-idf