MG_EV_HTTP_MSG not triggered on TLS + chunked responses

[GhoweVege]

• My goal is: Send and receive data from an ESP32 to a server using TLS and chunked encoding.
• My actions were: I programmed an ESP32 to send an update to a remote server that uses TLS and chunked encoding.
• My expectation was: That Mongoose would trigger MG_EV_HTTP_MSG when the full response, including the terminating chunk, was received and buffered, even when delivered over TLS.
• The result I saw: MG_EV_HTTP_MSG was not triggered. Only MG_EV_CLOSE fired, and the buffered data contained the full HTTP response. This only happens when TLS and chunked encoding are both used. Plain HTTP with chunked encoding works fine. TLS with non-chunked responses also works fine.
• My question is: Can the logic in the read_conn() function be changed to be closer to what was used in 7.15 so that MG_EV_HTTP_MSG gets triggered after the final terminating chunk arrives.

Environment

• mongoose version: 7.15, 7.16, 7.17
• Compiler/IDE and SDK: PlatformIO with ESP32 Arduino framework
• Target hardware/board: ESP32
• Connectivity chip/module: onboard WiFi (ESP32)
• Target RTOS/OS (if applicable): Arduino (no RTOS)

Overview

The original failure was observed after upgrading from 7.15 to 7.17 when sending updates from an ESP32 to a remote logging server.

I made a test server and ran lots of tests to narrow down exactly what is happening, and the MG_EV_HTTP_MSG only fails to trigger in one specific scenario: it fails when the server being contacted uses TLS and the response uses chunked encoding.

I tested further until I narrowed down the problem to a change in the logic used in the read_conn() function between versions 7.15 and 7.16.

I tested using the latest version (7.17), and just changing the logic of read_conn() back to what it was in 7.15, and that resolves the issue.

If you want it, I have minimal code that proves the failure, but you can probably make your own just as easily. On the ESP32 side, it is just a client that sends a request to a server and watches for the reply. The server side is a simple python server that can respond using chunked or normal encoding, and can toggle whether or not to use TLS.

My temporary workaround has been that when I get a 'MG_EV_CLOSE' event in my code, I check to see if I have received a response from the server, and if not, manually trigger a 'mg_http_parse()' on the receive buffer to see if there is valid data, and if so, I trigger a 'MG_EV_HTTP_MSG'.

[scaprile]

The logic was changed for a reason, and it served good purpose to get rid of other bugs while providing a smooth service under low memory conditions.
What you describe might be another bug that needs attention. Mongoose is probably thinking there was an error or giving up after some condition reported by your socket layer, hence not delivering your message.
Please sniff your network (using Wireshark, for example) and observe the traffic; then please provide us with pertinent information (including useful network capture files; no snapshots, please attach capture files) in order to reproduce the issue. We don't inspect your code for errors, please send the minimum piece of code that can reproduce the issue.
Please also include a DEBUG log and, if possible, a VERBOSE log.
Thank you

[GhoweVege]

Ok, here is the basic code, and I'm attaching both a debug log and a verbose log. I will get started on a Wireshark capture, and will post that when it is done.

#include <Arduino.h>
#include "mongoose.h"
#include <WiFi.h>

const char *ssid = "WiFi-SSID";
const char *password = "WiFi-PASSWORD";

static const char *s_url = "https://192.168.0.21:8443";

static struct mg_mgr mgr;
static bool done = false;

// Simple JSON body for test
const char *post_data = R"({"test":"data"})";

void cb(struct mg_connection *c, int ev, void *ev_data)
{
  if (ev == MG_EV_CONNECT)
  {
    Serial.println("Connected to server");
    struct mg_str host = mg_url_host(s_url);
    if (mg_url_is_ssl(s_url))
    {
      struct mg_tls_opts opts = {.ca = mg_str_n(nullptr, 0), .name = host};
      mg_tls_init(c, &opts);
    }

    mg_printf(c,
              "POST %s HTTP/1.1\r\n"
              "Host: %.*s\r\n"
              "Content-Type: application/json\r\n"
              "Content-Length: %d\r\n"
              "User-Agent: esp32-test\r\n"
              "Connection: close\r\n"
              "Accept: */*\r\n"
              "\r\n"
              "%s",
              mg_url_uri(s_url),
              (int)host.len, host.buf,
              strlen(post_data), post_data);
  }
  else if (ev == MG_EV_HTTP_MSG)
  {
    Serial.println("MG_EV_HTTP_MSG received");
    struct mg_http_message *hm = (struct mg_http_message *)ev_data;
    Serial.printf("Response:\n%.*s\n", (int)hm->message.len, hm->message.buf);
    done = true;
  }
  else if (ev == MG_EV_CLOSE)
  {
    if (!done)
    {
      Serial.println("MG_EV_CLOSE fired before MG_EV_HTTP_MSG — possible bug!");
    }
    else
    {
      Serial.println("Connection closed cleanly.");
    }
    done = true;
  }
}

void setup()
{
  Serial.begin(115200);
  delay(1000);
  Serial.println("Connecting to WiFi...");

  WiFi.begin(ssid, password);
  while (WiFi.status() != WL_CONNECTED)
  {
    delay(500);
    Serial.print(".");
  }

  Serial.println("\nWiFi connected.");
  mg_mgr_init(&mgr);
  mg_log_set(MG_LL_VERBOSE);
  mg_http_connect(&mgr, s_url, cb, NULL);
}

void loop()
{
  mg_mgr_poll(&mgr, 100);
}

fail_debug.log

fail_verbose.log

[GhoweVege]

Ok, here is the Wireshark capture of a failure. Let me know if there's anything else I can do to help.

fail_wireshark_capture.zip

[scaprile]

• Your Wireshark capture is missing (at least) half the traffic. I don't see any frames from host 21 --> to host 111
• Your TCP/IP stack is signalling an error: 904 3 mongoose.c:8239:read_conn 1 48 0:199:0 -1 err 128 (Transport endpoint is not connected)
• Your HTTPS server is an internal one, is it properly sending the last chunk indication ?
• You shouldn't be getting Weak RNG: using rand(), what is your mongoose_config.h ? You seem to have missed changes in arch,

  mongoose/tutorials/http/http-server/arduino/esp32-http/mongoose_config.h

  Lines 1 to 5 in 3861e2e

  	#pragma once
  	#include "Arduino.h"
  	#define MG_ARCH MG_ARCH_ESP32

My guess is that Mongoose can't know the transfer length in advance, so it waits until it ends, but the error comes first and so it discards data. Why does it work with no TLS ? I can't explain so far.
Please address and fix the subjects above, then send a raw transfer with no TLS, so I can see the HTTP flow and guess what it would be like in TLS. The ideal situation is that you also send a TLS capture with the session keys, so everything is shown. This requires tweaking your server for SSLKEYLOGFILE; and sending both capture and keys file https://wiki.wireshark.org/TLS#tls-decryption

Other possibility is that you post your server code (smallest piece that reproduces the issue), so we can reproduce it in our servers and test ourselves. Thank you.

[GhoweVege]

Ok, I will start working on all of that. Like I said, the problem was originally observed on a remote server (it was sending data to thingspeak.com), but I made a local python server so that I could have finer control in figuring out what was going on and flipping TLS/chunks on and off. I'll post that code here if you wan to use it, and then dive in to the rest of what you asked for.

from http.server import HTTPServer, BaseHTTPRequestHandler
import ssl

USE_CHUNKED_ENCODING = True  # << Toggle chunked encoding on/off here
USE_TLS = True  # << Toggle HTTPS on/off here
PORT = 8443 if USE_TLS else 8080
CERT_FILE = "cert.pem"
KEY_FILE = "key.pem"


class TestHandler(BaseHTTPRequestHandler):

    def do_POST(self):
        length = int(self.headers.get('Content-Length', 0))
        body = self.rfile.read(length)
        print(
            f"\n--- Received Request ---\n{self.requestline}\n{self.headers}\n{body.decode()}\n"
        )

        if USE_CHUNKED_ENCODING:
            self.send_response(202)
            self.send_header("Content-Type", "application/json")
            self.send_header("Transfer-Encoding", "chunked")
            self.send_header("Connection", "close")
            self.end_headers()

            response_body = '{"success":true}'
            chunk = f"{len(response_body):X}\r\n{response_body}\r\n"
            terminator = "0\r\n\r\n"

            self.wfile.write(chunk.encode())
            self.wfile.write(terminator.encode())
        else:
            response_body = '{"success":true}'
            self.send_response(202)
            self.send_header("Content-Type", "application/json")
            self.send_header("Content-Length", str(len(response_body)))
            self.send_header("Connection", "close")
            self.end_headers()
            self.wfile.write(response_body.encode())

        self.wfile.flush()

        print(
            f"--> Sent {'chunked' if USE_CHUNKED_ENCODING else 'non-chunked'} response over {'HTTPS' if USE_TLS else 'HTTP'} -->\n"
        )

    def log_message(self, format, *args):
        return


def run():
    server_address = ('0.0.0.0', PORT)
    httpd = HTTPServer(server_address, TestHandler)

    if USE_TLS:
        context = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
        context.load_cert_chain(certfile=CERT_FILE, keyfile=KEY_FILE)
        httpd.socket = context.wrap_socket(httpd.socket, server_side=True)

        print(
            f"Serving on https://0.0.0.0:{PORT} (chunked={USE_CHUNKED_ENCODING})..."
        )
    else:
        print(
            f"Serving on http://0.0.0.0:{PORT} (chunked={USE_CHUNKED_ENCODING})..."
        )

    httpd.serve_forever()


if __name__ == '__main__':
    run()

[GhoweVege]

You were right about the mongoose_config.h, I forgot that I had messed around with some custom settings in there. I changed it back to #define MG_ARCH MG_ARCH_ESP32. It didn't fix the bug, but it got rid of Weak RNG: using rand(). Here are some updated logs.

fail_debug.log
fail_verbose.log

[scaprile]

Thanks, I'll see what I can reproduce next week.
Meanwhile, there are two things you can try.
This is the part missing from your capture, I have the hunch that the server is setting the FIN flag on its last TLS record, and that triggers a condition we haven't see so far on the other stacks we tested.

In readconn():

        if (c->rtls.len == 0 || m < 0) {
          // Close only when we have fully drained both rtls and TLS buffers
          c->is_closing = 1;  // or there's nothing we can do about it.
          m = MG_IO_ERR;

• Test 1:
  • change if (c->rtls.len == 0 || m < 0) { to if (c->rtls.len == 0 && m < 0) {
• Test 2:
  • change m = MG_IO_ERR; to if (m < 0) m = MG_IO_ERR;

Please try both independently, they are mutually exclusive. Please send me the DEBUG logs.
Mods in Test 2 are probably harmless, but those in Test 1 are very intrusive, please don't take this as a fix, even if it works as such, I just want to see what is going on and then we'll test with other TCP/IP stacks, and possibly TLS libraries.

BTW, what is your TLS config ? I guess you'd just MG_TLS = MG_TLS_MBED; please confirm.

PS: based on your latest log, my money is on Test 2

[GhoweVege]

Ok, I will start on those tests next. I just finished getting my Wireshark captures sorted out. I'll attach one that uses chunked encoding with no TLS, and another that uses chunked and TLS, but now has TLS decrypted. Both files should now have the traffic from both the server and the client.

wireshark_.zip

[GhoweVege]

To confirm, yes I am using MG_TLS = MG_TLS_MBED;

[GhoweVege]

Ok, I tested each of those changes separately, and each one fixed the problem. I am attaching the logs for each.

test1_result.log
test2_result.log

[scaprile]

Great, but Test1 is prone to trigger other failure modes, like never closing a connection that failed with a fragmented TLS record in the buffer.
I'll check all this info next week, run some tests, and issue a PR with the fix. Thank you for your help.

[GhoweVege]

Thank you for being so responsive! If there's anything else I can help with, just let me know.