Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Websocket server cannot handle big messages (IDFGH-5463) #7202

Closed
ProgrMike opened this issue Jun 28, 2021 · 18 comments
Closed

Websocket server cannot handle big messages (IDFGH-5463) #7202

ProgrMike opened this issue Jun 28, 2021 · 18 comments
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally

Comments

@ProgrMike
Copy link

Environment

  • Development Kit: ESP32-DevKitC
  • Kit version (for DevKitC): v4
  • Module or chip used: ESP32-WROOM-32
  • IDF version: v4.3
  • Build System: idf.py
  • Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2020r3) 8.4.0
  • Operating System: Windows
  • (Windows only) environment type: ESP Command Prompt
  • Using an IDE?: Yes
    VS Code with Espressif IDF Extension v1.1.0
  • Power Supply: USB

Problem Description

The Websocket handler in the httpd server has a problem handling larger incoming data. When a client sends this much data a few times, the ESP seems to mix something up and receives wrong packet type, followed by message "httpd_ws_recv_frame: WS frame is not properly masked." during httpd_ws_recv_frame(). Typically this doesn't happen on the first frame and not everytime on the same consecutive one, but it happens guaranteed and consistently within the next 50 incoming messages. Though it is very likely to happen in the next 5.

After testing the limits I'm pretty sure this only happens when receiving messages with length 1433 bytes and up. Did not see it with less bytes yet.

Expected Behavior

The messages should be received correctly each time for a message length >= 1433 Bytes.

Actual Behavior

As the example run further down shows, the first message is received correctly, the second one already has a '0' instead of 'D' at the end which indicates something is messed up. The third time len is 1, type is wrong and the message is not readable. The fourth time an error is detected (WS frame not properly masked) and the connection ends there with the log "httpd_ws_recv_frame: WS frame is not properly masked."

Steps to reproduce

  1. Load Websocket Echo Server example
  2. Replace the existing echo_handler() with the code below. Note that there is a global buffer variable.
  3. Build & Flash to ESP
  4. When ESP connected to the AP, edit the URI variable in the Python script below and start the Python script
  5. The Python script prints a number every time it starts a new loop. The variable NUM_BYTES controls how many bytes will be sent to ESP. For a value of 1432 and less, it doesn't fail. For 1433 and above it fails after a few messages.

Code to reproduce this issue

I used the example from Websocket Echo Server with the following URI handler:

#define BUF_SIZE 7680
static uint8_t buf[BUF_SIZE + 1] = { 0 };

static esp_err_t echo_handler(httpd_req_t *req)
{
    ESP_LOGI(TAG, "Entering ws_handler()");
    httpd_ws_frame_t ws_pkt;
    memset(&ws_pkt, 0, sizeof(httpd_ws_frame_t));
    ws_pkt.payload = buf;
    ws_pkt.type = HTTPD_WS_TYPE_TEXT;
    esp_err_t ret = httpd_ws_recv_frame(req, &ws_pkt, BUF_SIZE);
    if (ret != ESP_OK) {
        ESP_LOGE(TAG, "httpd_ws_recv_frame failed with %s", esp_err_to_name(ret));
        return ret;
    }
    ws_pkt.payload[ws_pkt.len] = 0;     // Null-termination
    ESP_LOGI(TAG, "Got packet with type=%d, len=%u and message: %s", ws_pkt.type, ws_pkt.len, ws_pkt.payload);
    ret = httpd_ws_send_frame(req, &ws_pkt);
    ESP_LOGI(TAG, "httpd_ws_send_frame returned with %s", esp_err_to_name(ret));
    return ret;
}

As a client I used this python script:

import asyncio
import websockets

URI = "ws://192.168.30.190/ws" # Change to ESP IP here
LONG_DATA = "Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Duis autem vel eum iriure dolor in hendrerit in vulputate velit esse molestie consequat, vel illum dolore eu feugiat nulla facilisis at vero eros et accumsan et iusto odio dignissim qui blandit praesent luptatum zzril delenit augue duis dolore te feugait nulla facilisi. Lorem ipsum dolor sit amet, consectetuer adipiscing elit, sed diam nonummy nibh euismod tincidunt ut laoreet dolore magna aliquam erat volutpat. Ut wisi enim ad minim veniam, quis nostrud exerci tation ullamcorper suscipit lobortis nisl ut aliquip ex ea commodo consequat. Duis autem vel eum iriure dolor in hendrerit in vulputate velit esse molestie consequat, vel illum dolore eu feugiat nulla"
NUM_BYTES = 1433 # Fails with 1433, works with 1432
NUM_TIMES = 50

async def startTest():
    data = ""
    for i in range(NUM_BYTES):
        data+=LONG_DATA[i]
    async with websockets.connect(URI) as websocket:
        count = 1
        print(f"Full data (len={len(data)}) is {data}")
        while count <= NUM_TIMES:
            print(f"{count}")
            await websocket.send(data)
            received = await websocket.recv()
            # print(f"Received '{received}'")
            count += 1
        await websocket.close()
asyncio.get_event_loop().run_until_complete(startTest())

Debug Logs

I (14993) ws_echo_server: Entering ws_handler()
I (14993) ws_echo_server: Got packet with type=1, len=1433 and message: Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Duis autem vel eum iriure dolor in hendrerit in vulputate velit esse molestie consequat, vel illum dolore eu feugiat nulla facilisis at vero eros et accumsan et iusto odio dignissim qui blandit praesent luptatum zzril delenit augue duis dolore te feugait nulla facilisi. Lorem ipsum dolor sit amet, consectetuer adipiscing elit, sed diam nonummy nibh euismod tincidunt ut laoreet dolore magna aliquam erat volutpat. Ut wisi enim ad minim veniam, quis nostrud exerci tation ullamcorper suscipit lobortis nisl ut aliquip ex ea commodo consequat. D     
I (15113) ws_echo_server: httpd_ws_send_frame returned with ESP_OK
I (15203) ws_echo_server: Entering ws_handler()
I (15203) ws_echo_server: Got packet with type=1, len=1433 and message: Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Duis autem vel eum iriure dolor in hendrerit in vulputate velit esse molestie consequat, vel illum dolore eu feugiat nulla facilisis at vero eros et accumsan et iusto odio dignissim qui blandit praesent luptatum zzril delenit augue duis dolore te feugait nulla facilisi. Lorem ipsum dolor sit amet, consectetuer adipiscing elit, sed diam nonummy nibh euismod tincidunt ut laoreet dolore magna aliquam erat volutpat. Ut wisi enim ad minim veniam, quis nostrud exerci tation ullamcorper suscipit lobortis nisl ut aliquip ex ea commodo consequat. 0     
I (15333) ws_echo_server: httpd_ws_send_frame returned with ESP_OK
I (15333) ws_echo_server: Entering ws_handler()
I (15393) ws_echo_server: Got packet with type=0, len=1 and message: �
I (15393) ws_echo_server: httpd_ws_send_frame returned with ESP_OK
I (15403) ws_echo_server: Entering ws_handler()
W (15403) httpd_ws: httpd_ws_recv_frame: WS frame is not properly masked.
E (15413) ws_echo_server: httpd_ws_recv_frame failed with ESP_ERR_INVALID_STATE
@espressif-bot espressif-bot added the Status: Opened Issue is new label Jun 28, 2021
@github-actions github-actions bot changed the title Websocket server cannot handle big messages Websocket server cannot handle big messages (IDFGH-5463) Jun 28, 2021
@ESP-YJM
Copy link
Collaborator

ESP-YJM commented Jun 29, 2021

@Osetinski Thanks for producing detailed steps to reproduce the issue. We will take into a look and reply you ASAP.

@ESP-YJM
Copy link
Collaborator

ESP-YJM commented Jun 30, 2021

@Osetinski What IDF version you uesd. I use tag v4.3 version with your code and script. It's ok for me. Could you please check your IDF version and update to v4.3 to test.

@espressif-bot espressif-bot added Status: In Progress Work is in progress and removed Status: Opened Issue is new labels Jun 30, 2021
@ProgrMike
Copy link
Author

@ESP-YJM Thanks for the quick response. I am sure I'm using v4.3. I get the following result for git describe command in my esp idf directory:

$ git describe --tags
v4.3

Additionally the Bootloader logs the following during startup:

I (29) boot: ESP-IDF v4.3 2nd stage bootloader

Doesn't the communication abort for you at all? I always get at least unclear messages (like the third one in my log above) in the ESP log and some kind of "connection closed abnormally" error during execution of the Python script.

@ESP-YJM
Copy link
Collaborator

ESP-YJM commented Jun 30, 2021

@Osetinski What about your python version? ESP32 ws_echo_server can successfully receive 50 counts data with length 1433 in my environment.

@ProgrMike
Copy link
Author

@ESP-YJM Okay, that's confusing. Could you try more Bytes? Maybe up to 1600? You might need to update the LONG_DATA variable in my script so it contains more characters.
My Python version is 3.9.2. But I'm having this problem from JavaScript in different Browsers (Edge, Chrome, Firefox), too. I don't think this is a Python problem. Maybe it's a problem with the network, what do you think?

@ESP-YJM
Copy link
Collaborator

ESP-YJM commented Jun 30, 2021

@ESP-YJM Okay, that's confusing. Could you try more Bytes? Maybe up to 1600? You might need to update the LONG_DATA variable in my script so it contains more characters.
My Python version is 3.9.2. But I'm having this problem from JavaScript in different Browsers (Edge, Chrome, Firefox), too. I don't think this is a Python problem. Maybe it's a problem with the network, what do you think?

Ok, i will test it with larger bytes. And will response you my result ASAP.

@ESP-YJM
Copy link
Collaborator

ESP-YJM commented Jun 30, 2021

@Osetinski I change the length to 1600, it's also ok for me. Could you use wireshark to capture the packet.
图片

@ProgrMike
Copy link
Author

@ESP-YJM I tried to capture the packets with Wireshark, though I was not exactly sure how to properly export it. Please find the exported file here. 192.168.30.176 is the IP of the ESP, while 192.168.30.147 is the IP of my PC. I guess the most interesting frames are 280 and 297. Frame 280 shows that the whole packet is transmitted correctly over the network to the ESP. Frame 297 is the echo from ESP back to PC and seems to have some kind mixed up data.

This is how frame 280 looks like in Wireshark:
grafik
It contains the correct full data and is correctly masked.

Then frame 297 looks like this:
grafik
You can see there already seems to be something wrong where it says "WebSocket Text [FIN] WebSocket Pong [FIN]". So there seems to be a message with opcode text and then another with opcode Pong for some reason.

The payload of frame 297 is the one, where some wrong data is echo'd back, just as it was output in the log console. Console log looks like this:
grafik
Payload of frame 297 looks like this:
grafik

Payload of frame 280 is correct at the end:
grafik

Frame 299 closes the connection, which is initiated from PC, because the Python script throws an exception at this point. Concrete error:
grafik

@ESP-YJM
Copy link
Collaborator

ESP-YJM commented Jun 30, 2021

@Osetinski Could you please share your whole wireshark capture file instead of txt file. I think it maybe caused by PING & PONG packet. But i didn't capture any PING & PONG packet in my environment.

@ProgrMike
Copy link
Author

@ESP-YJM Yeah sorry that makes sense. Here you can download the capture file, filtered by IP 192.168.30.176 (my ESP's IP). Thanks again for your time.

@ESP-YJM
Copy link
Collaborator

ESP-YJM commented Jul 1, 2021

@Osetinski Thanks for your capture file. It seems our ESP device reply PONG packet to your PC and the Python script can not handle it properly, maybe need add logic to handle PONG type data. Besides, i don't know where and which packet that client send PING packet in capture file. Maybe need change LOG level from info to debug in ESP to check.

@ProgrMike
Copy link
Author

@ESP-YJM On second thought I think the PONG-Opcode might be misleading and more of a coincidence. Sometimes I saw other opcodes too, which aren't even specified e.g. opcode=5. I guess it is just some kind of random data written to the stream and being misinterpreted in this case as a PONG-packet with opcode 10.

As you suggested I ran it with LOG level set to debug. Please find the log file here.

I also swapped the line sending the websocket packets in the Python script with this:

await websocket.send(str(count).zfill(3) + data)

This way you can keep track of the message from ESP Log. From the log file I can read on the last received data, that 1453 should be read, but only 1432 could be received correctly. Still the handler gets the length 1453, which explains the random symbols at the end of the logged message. Hope it helps.

@ESP-YJM
Copy link
Collaborator

ESP-YJM commented Jul 1, 2021

@Osetinski Could you please modify code like this and re-try

--- a/components/esp_http_server/src/httpd_parse.c
+++ b/components/esp_http_server/src/httpd_parse.c
@@ -489,7 +489,7 @@ static int read_block(httpd_req_t *req, size_t offset, size_t length)
     struct httpd_req_aux *raux  = req->aux;
 
     /* Limits the read to scratch buffer size */
-    ssize_t buf_len = MIN(length, (sizeof(raux->scratch) - offset));
+    ssize_t buf_len = MIN(length, (sizeof(raux->scratch) - 1 - offset));
     if (buf_len <= 0) {
         return 0;
     }
diff --git a/components/esp_http_server/src/httpd_txrx.c b/components/esp_http_server/src/httpd_txrx.c
index ab16f5f..eaa9596 100644
--- a/components/esp_http_server/src/httpd_txrx.c
+++ b/components/esp_http_server/src/httpd_txrx.c
@@ -107,6 +107,7 @@ int httpd_recv_with_opt(httpd_req_t *r, char *buf, size_t buf_len, bool halt_aft
     ESP_LOGD(TAG, LOG_FMT("requested length = %d"), buf_len);
 
     size_t pending_len = 0;
+    int ret = 0;
     struct httpd_req_aux *ra = r->aux;
 
     /* First fetch pending data from local buffer */
@@ -125,20 +126,26 @@ int httpd_recv_with_opt(httpd_req_t *r, char *buf, size_t buf_len, bool halt_aft
     }
 
     /* Receive data of remaining length */
-    int ret = ra->sd->recv_fn(ra->sd->handle, ra->sd->fd, buf, buf_len, 0);
-    if (ret < 0) {
-        ESP_LOGD(TAG, LOG_FMT("error in recv_fn"));
-        if ((ret == HTTPD_SOCK_ERR_TIMEOUT) && (pending_len != 0)) {
-            /* If recv() timeout occurred, but pending data is
-             * present, return length of pending data.
-             * This behavior is similar to that of socket recv()
-             * function, which, in case has only partially read the
-             * requested length, due to timeout, returns with read
-             * length, rather than error */
-            return pending_len;
+    while (buf_len > 0) {
+        ret = ra->sd->recv_fn(ra->sd->handle, ra->sd->fd, buf + ret, buf_len, 0);
+        if (ret < 0) {
+            ESP_LOGD(TAG, LOG_FMT("error in recv_fn"));
+            if ((ret == HTTPD_SOCK_ERR_TIMEOUT) && (pending_len != 0)) {
+                /* If recv() timeout occurred, but pending data is
+                * present, return length of pending data.
+                * This behavior is similar to that of socket recv()
+                * function, which, in case has only partially read the
+                * requested length, due to timeout, returns with read
+                * length, rather than error */
+                return pending_len;
+            }
+            return ret;
         }
-        return ret;
-    }
+        if (buf_len > ret) {
+            ESP_LOGW(TAG, "recv data length is less than the data length we want. Read again!");
+        }
+        buf_len -= ret;
+    };
 

@ProgrMike
Copy link
Author

@ESP-YJM I modified the code as you said, this is what I get:

D (3992) httpd: httpd_thread: web server started
D (4002) httpd: httpd_server: doing select maxfd+1 = 56
D (4012) httpd_uri: httpd_register_uri_handler: [0] installed /ws
W (10242) wifi:<ba-add>idx:0 (ifx:0, f4:f2:6d:35:24:ec), tid:0, ssn:0, winSize:64
D (10542) httpd: httpd_server: processing listen socket 54
D (10542) httpd: httpd_accept_conn: newfd = 57
D (10542) httpd_sess: httpd_sess_new: fd = 57
D (10552) httpd: httpd_accept_conn: complete
D (10552) httpd: httpd_server: doing select maxfd+1 = 58
D (10862) httpd: httpd_server: processing socket 57
D (10862) httpd_sess: httpd_sess_process: httpd_req_new
D (10862) httpd_parse: httpd_req_new: New request, has WS? No, sd->ws_handler valid? No, sd->ws_close? No
D (10872) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (10872) httpd_txrx: httpd_recv_with_opt: received length = 128
D (10882) httpd_parse: read_block: received HTTP request block size = 128
D (10892) httpd_parse: cb_url: message begin
D (10892) httpd_parse: cb_url: processing url = /ws
D (10902) httpd_parse: verify_url: received URI = /ws
D (10902) httpd_parse: cb_header_field: headers begin
D (10912) httpd_txrx: httpd_unrecv: length = 110
D (10912) httpd_parse: pause_parsing: paused
D (10922) httpd_parse: cb_header_field: processing field = Host
D (10922) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (10932) httpd_txrx: httpd_recv_with_opt: pending length = 110
D (10932) httpd_parse: read_block: received HTTP request block size = 110
D (10942) httpd_parse: continue_parsing: skip pre-parsed data of size = 5
D (10952) httpd_parse: continue_parsing: un-paused
D (10952) httpd_parse: cb_header_value: processing value = 192.168.30.176
D (10962) httpd_parse: cb_header_field: processing field = Upgrade
D (10972) httpd_parse: cb_header_value: processing value = websocket
D (10972) httpd_parse: cb_header_field: processing field = Connection
D (10982) httpd_parse: cb_header_value: processing value = Upgrade
D (10982) httpd_parse: cb_header_field: processing field = Sec-WebSocket-Key
D (10992) httpd_parse: cb_header_value: processing value = fSKGt+vDldxP3no7gX2GsA==
D (11002) httpd_parse: cb_header_field: processing field = Se
D (11002) httpd_parse: parse_block: parsed block size = 110
D (11012) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (11022) httpd_txrx: httpd_recv_with_opt: received length = 128
D (11022) httpd_parse: read_block: received HTTP request block size = 128
D (11032) httpd_parse: cb_header_field: processing field = c-WebSocket-Version
D (11042) httpd_parse: cb_header_value: processing value = 13
D (11042) httpd_parse: cb_header_field: processing field = Sec-WebSocket-Extensions
D (11052) httpd_parse: cb_header_value: processing value = permessage-deflate; client_max_window_bits
D (11062) httpd_parse: cb_header_field: processing field = User-Agent
D (11072) httpd_parse: cb_header_value: processing value = Python/3.9 websockets
D (11072) httpd_parse: parse_block: parsed block size = 238
D (11082) httpd_txrx: httpd_recv_with_opt: requested length = 128
W (11092) httpd_txrx: recv data length is less than the data length we want. Read again!
W (16092) httpd_txrx: httpd_sock_err: error in recv : 11
D (16092) httpd_txrx: httpd_recv_with_opt: error in recv_fn
D (16092) httpd_parse: read_block: error in httpd_recv
W (16092) httpd_txrx: httpd_resp_send_err: 408 Request Timeout - Server closed this connection
D (16102) httpd_txrx: httpd_send_all: sent = 75
D (16112) httpd_txrx: httpd_send_all: sent = 2
D (16112) httpd_txrx: httpd_send_all: sent = 29
D (16112) httpd: httpd_server: closing socket 57
D (16122) httpd_sess: httpd_sess_delete: fd = 57
D (16122) httpd: httpd_server: doing select maxfd+1 = 56

@ESP-YJM
Copy link
Collaborator

ESP-YJM commented Jul 1, 2021

@Osetinski Did you change code here

--- a/components/esp_http_server/src/httpd_parse.c
+++ b/components/esp_http_server/src/httpd_parse.c
@@ -489,7 +489,7 @@ static int read_block(httpd_req_t *req, size_t offset, size_t length)
     struct httpd_req_aux *raux  = req->aux;
 
     /* Limits the read to scratch buffer size */
-    ssize_t buf_len = MIN(length, (sizeof(raux->scratch) - offset));
+    ssize_t buf_len = MIN(length, (sizeof(raux->scratch) - 1 - offset));
     if (buf_len <= 0) {
         return 0;
     }

@ProgrMike
Copy link
Author

@ESP-YJM Yes I did

@ESP-YJM
Copy link
Collaborator

ESP-YJM commented Jul 1, 2021

@Osetinski Please revert the previous changes and test again according to the following changes.

+++ b/components/esp_http_server/src/httpd_ws.c
@@ -332,9 +332,16 @@ esp_err_t httpd_ws_recv_frame(httpd_req_t *req, httpd_ws_frame_t *frame, size_t
         return ESP_FAIL;
     }
 
-    if (httpd_recv_with_opt(req, (char *)frame->payload, frame->len, false) <= 0) {
-        ESP_LOGW(TAG, LOG_FMT("Failed to receive payload"));
-        return ESP_FAIL;
+    int read_len = 0, left_len = frame->len;
+    while (left_len > 0) {
+        if ((read_len = httpd_recv_with_opt(req, (char *)frame->payload + read_len, left_len, false)) <= 0) {
+            ESP_LOGW(TAG, LOG_FMT("Failed to receive payload"));
+            return ESP_FAIL;
+        }
+        if (left_len > read_len) {
+            ESP_LOGW(TAG, "recv data length is less than the data length we want. Read again!");
+        }
+        left_len -= read_len;
     }

@ProgrMike
Copy link
Author

@ESP-YJM Yes, this seems to fix the problem! The log also proofs that now all Bytes are received when reading multiple times as well as when all Bytes are received with one call:

I (292343) ws_echo_server: Entering echo_handler()
D (292353) httpd_txrx: httpd_recv_with_opt: requested length = 1
D (292363) httpd_txrx: httpd_recv_with_opt: received length = 1
D (292363) httpd_txrx: httpd_recv_with_opt: requested length = 2
D (292373) httpd_txrx: httpd_recv_with_opt: received length = 2
D (292373) httpd_txrx: httpd_recv_with_opt: requested length = 4
D (292383) httpd_txrx: httpd_recv_with_opt: received length = 4
D (292393) httpd_txrx: httpd_recv_with_opt: requested length = 2003
D (292403) httpd_txrx: httpd_recv_with_opt: received length = 1432
W (292403) httpd_ws: recv data length is less than the data length we want. Read again!   
D (292413) httpd_txrx: httpd_recv_with_opt: requested length = 571
D (292413) httpd_txrx: httpd_recv_with_opt: received length = 571
I (292423) ws_echo_server: Got packet with type=1, len=2003 and message: 035Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos 
et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Duis autem vel eum iriure 
dolor in hendrerit in vulputate velit esse molestie consequat, vel illum dolore eu feugiat nulla facilisis at vero eros et accumsan et iusto odio dignissim qui blandit praesent luptatum zzril delenit augue duis dolore te feugait nulla facilisi. Lorem ipsum dolor sit amet, consectetuer adipiscing elit, sed diam nonummy nibh euismod tincidunt ut laoreet dolore magna aliquam erat volutpat. Ut wisi enim ad minim veniam, quis nostrud exerci tation ullamcorper suscipit lobortis nisl ut aliquip ex ea commodo consequat. Duis autem vel eum iriure dolor in hendrerit in vulputate velit esse molestie consequat, vel illum dolore eu feugiat nulla facilisis at vero eros et accumsan et iusto odio dignissim qui blandit praesent luptatum zzril delenit augue duis dolore te feugait nulla facilisi. Nam liber tempor cum 
soluta nobis eleifend option congue nihil imperdiet doming id quod mazim placerat facer possim assum. Lorem ipsum dolor sit amet, consectetuer adipiscing elit, sed diam nonummy nibh euismod tincidunt ut laoreet dolore magna aliquam erat volutpat. Ut wisi enim ad minim veniam,
I (292603) ws_echo_server: httpd_ws_send_frame returned with ESP_OK
D (292613) httpd_sess: httpd_sess_process: httpd_req_delete
D (292613) httpd_sess: httpd_sess_process: success
D (292623) httpd: httpd_server: doing select maxfd+1 = 58
D (293093) httpd: httpd_server: processing socket 57
D (293093) httpd_sess: httpd_sess_process: httpd_req_new
D (293093) httpd_parse: httpd_req_new: New request, has WS? Yes, sd->ws_handler valid? Yes, sd->ws_close? No
D (293103) httpd_txrx: httpd_recv_with_opt: requested length = 1
D (293113) httpd_txrx: httpd_recv_with_opt: received length = 1
D (293113) httpd_ws: httpd_ws_get_frame_type: First byte received: 0x81
D (293123) httpd_parse: httpd_req_new: New WS request from existing socket, ws_type=1     
I (293133) ws_echo_server: Entering echo_handler()
D (293133) httpd_txrx: httpd_recv_with_opt: requested length = 1
D (293143) httpd_txrx: httpd_recv_with_opt: received length = 1
D (293143) httpd_txrx: httpd_recv_with_opt: requested length = 2
D (293153) httpd_txrx: httpd_recv_with_opt: received length = 2
D (293163) httpd_txrx: httpd_recv_with_opt: requested length = 4
D (293163) httpd_txrx: httpd_recv_with_opt: received length = 4
D (293173) httpd_txrx: httpd_recv_with_opt: requested length = 2003
D (293183) httpd_txrx: httpd_recv_with_opt: received length = 2003
I (293183) ws_echo_server: Got packet with type=1, len=2003 and message: 036Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos 
et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Lorem ipsum dolor sit amet, consetetur sadipscing elitr, sed diam nonumy eirmod tempor invidunt ut labore et dolore magna aliquyam erat, sed diam voluptua. At vero eos et accusam et justo duo dolores et ea rebum. Stet clita kasd gubergren, no sea takimata sanctus est Lorem ipsum dolor sit amet. Duis autem vel eum iriure 
dolor in hendrerit in vulputate velit esse molestie consequat, vel illum dolore eu feugiat nulla facilisis at vero eros et accumsan et iusto odio dignissim qui blandit praesent luptatum zzril delenit augue duis dolore te feugait nulla facilisi. Lorem ipsum dolor sit amet, consectetuer adipiscing elit, sed diam nonummy nibh euismod tincidunt ut laoreet dolore magna aliquam erat volutpat. Ut wisi enim ad minim veniam, quis nostrud exerci tation ullamcorper suscipit lobortis nisl ut aliquip ex ea commodo consequat. Duis autem vel eum iriure dolor in hendrerit in vulputate velit esse molestie consequat, vel illum dolore eu feugiat nulla facilisis at vero eros et accumsan et iusto odio dignissim qui blandit praesent luptatum zzril delenit augue duis dolore te feugait nulla facilisi. Nam liber tempor cum 
soluta nobis eleifend option congue nihil imperdiet doming id quod mazim placerat facer possim assum. Lorem ipsum dolor sit amet, consectetuer adipiscing elit, sed diam nonummy nibh euismod tincidunt ut laoreet dolore magna aliquam erat volutpat. Ut wisi enim ad minim veniam,
I (293363) ws_echo_server: httpd_ws_send_frame returned with ESP_OK

Also tested it in my actual setup, where the problem first appeared, and it works there too.

Thank you again for all your time and effort!

loganfin pushed a commit to Lumenaries/esp_http_server that referenced this issue Apr 23, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally
Projects
None yet
Development

No branches or pull requests

3 participants