Communication delay problem using urequest.

[peetery]

Hi!
I'm programming ESP32 using MicroPython and I I have encountered a problem with sending a POST request to the server using the urequest library. I have noticed that the communication speed is not stable and also always at a minimum of 1500ms and often takes up to 3000-5000ms. I need to send a POST request with json content, in response to this POST I also get a json from the server which I need to process on the device. I wanted this communication to be as fast as possible, so because I noticed such delays I stated that I would try sending a post with the header connection: keep-alive. But unfortunately it's not as easy as I thought and I don't even know if I can do it in MicroPython.

After adding some debugging logs, I came to the conclusion that this part of the code in urequest takes the most time:
if proto == "https:":'
context = tls.SSLContext(tls.PROTOCOL_TLS_CLIENT)
context.verify_mode = tls.CERT_NONE
s = context.wrap_socket(s, server_hostname=host)
and precisely the execution of the wrap_socket takes about 1000ms. That's why I concluded that maybe a keep-alive connection implementation would solve this problem.

I was fairly successful in getting a response from the server with the data, but there was a problem when trying response.json(). I had to wait about 70 seconds before the device parsed the response into json.
Looking further into the cause of the delay, I added a short code with logs and slightly changed the urequest implementation:

def read_full_response(socket, max_duration=5000):
    response_data = b""
    start_time = time.ticks_ms()

    while True:
        elapsed_time = time.ticks_diff(time.ticks_ms(), start_time)
        if elapsed_time > max_duration:
            print("[DEBUG] Timeout: Exceeded max read duration.")
            break

        chunk = socket.read(4096)
        if not chunk:
            print("[DEBUG] End of data stream.")
            break

        response_data += chunk
        print(f"[DEBUG] Chunk received: {len(chunk)} bytes, Total received: {len(response_data)} bytes")
        time.sleep_ms(5)

    total_time = time.ticks_diff(time.ticks_ms(), start_time)
    print(f"[DEBUG] Total read time: {total_time} ms")
    return response_data.decode('utf-8')

class Response:
    def __init__(self, f):
        self.raw = f
        self.encoding = "utf-8"
        self._cached = None

    def close(self):
        if self.raw:
            #self.raw.close()
            self.raw = None
        self._cached = None

    @property
    def content(self):
        if self._cached is None:
            try:
                self._cached = read_full_response(self.raw)
            finally:
                #self.raw.close()
                self.raw = None
        return self._cached

    @property
    def text(self):
        return str(self.content, self.encoding)

    def json(self):
        import json
        print("[DEBUG] Before importing data to content_text")
        content_text = self.text
        print("[DEBUG] Before json.loads")
        return json.loads(content_text)

    def release(self):
        self._cached = None

In addition, I have also simplified the request method to suit only my needs, added debugging logs and I added some code to support a keep-alive connection as far as MicroPython is concerned:

def request(
        method,
        url,
        data=None,
        headers=None,
        timeout=None,
        keep_alive_socket=None
):
    global tls_context
    start_time = time.ticks_ms()
    print(f"[DEBUG] Start request: {method} {url}")

    if headers is None:
        headers = {}

    proto, dummy, host, path = url.split("/", 3) if "/" in url else (url, "", host, "")
    port = 80 if proto == "http:" else 443

    ai = socket.getaddrinfo(host, port, 0, socket.SOCK_STREAM)
    ai = ai[0]

    if keep_alive_socket is None:
        s = socket.socket(ai[0], socket.SOCK_STREAM, ai[2])
        s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)

        #if timeout is not None:
        #    s.settimeout(timeout)

        s.connect(ai[-1])
        print(f"[DEBUG] Socket connection established: {time.ticks_diff(time.ticks_ms(), start_time)} ms")

        if proto == "https:":
            if tls_context is None:
                print(f"[DEBUG] tls_context is None, context inicialization: {time.ticks_diff(time.ticks_ms(), start_time)} ms")
                tls_context = tls.SSLContext(tls.PROTOCOL_TLS_CLIENT)
                tls_context.verify_mode = tls.CERT_NONE
        
            print(f"[DEBUG] Before wrapping socket: {time.ticks_diff(time.ticks_ms(), start_time)} ms")
            s = tls_context.wrap_socket(s, server_hostname=host)
            print(f"[DEBUG] Socket wrapped succesfully: {time.ticks_diff(time.ticks_ms(), start_time)} ms")
            
        keep_alive_socket = s

    headers["Host"] = host
    headers["Connection"] = "keep-alive"

    if data is not None:
        headers["Content-Length"] = str(len(data))

    if headers is not None:
        print(f"[DEBUG] Sending headers: {headers}")

    if data is not None:
        print(f"[DEBUG] Sending data: {data}")

    print(f"[DEBUG] Before header_buffer: {time.ticks_diff(time.ticks_ms(), start_time)} ms")
    header_buffer = f"{method} /{path} HTTP/1.1\r\n" + ''.join(f"{k}: {v}\r\n" for k, v in headers.items()) + "\r\n"
    print(f"[DEBUG] Before writing to socket: {time.ticks_diff(time.ticks_ms(), start_time)} ms")
    keep_alive_socket.write(header_buffer.encode('utf-8'))

    print(f"[DEBUG] Headers sent: {time.ticks_diff(time.ticks_ms(), start_time)} ms")

    if data is not None:
        keep_alive_socket.write(data)

    l = keep_alive_socket.readline()
    l = l.split(None, 2)
    if len(l) < 2:
        raise ValueError("HTTP error: BadStatusLine:\n%s" % l)
    status = int(l[1])

    print(f"[DEBUG] Status line read: {time.ticks_diff(time.ticks_ms(), start_time)} ms")

    resp_d = {}
    while True:
        l = keep_alive_socket.readline()
        if not l or l == b"\r\n":
            break
        k, v = str(l, "utf-8").split(":", 1)
        resp_d[k] = v.strip()

    print(f"[DEBUG] Status headers read: {time.ticks_diff(time.ticks_ms(), start_time)} ms")

    resp = Response(keep_alive_socket)
    resp.status_code = status
    resp.headers = resp_d
    
    print(f"[DEBUG] Request completed: {time.ticks_diff(start_time, time.ticks_ms())} ms")
    return resp, keep_alive_socket

And then I noticed in the REPL:

[DEBUG] Start request: POST (here was the address)
[DEBUG] Socket connection established: 418 ms
[DEBUG] tls_context is None, context inicialization: 532 ms
[DEBUG] Before wrapping socket: 535 ms
[DEBUG] Socket wrapped succesfully: 1996 ms
[DEBUG] Sending headers: {'Host': 'here was host address', 'Content-Length': '702', 'Connection': 'keep-alive'}
[DEBUG] Sending data: {here was the json data}
[DEBUG] Before header_buffer: 2129 ms
[DEBUG] Before writing to socket: 2236 ms
[DEBUG] Headers sent: 2242 ms
[DEBUG] Status line read: 2486 ms
[DEBUG] Status headers read: 2493 ms

[DEBUG] Request completed: 2494 ms
<Response object at 3ffdaae0>
ONLY response time:  2499 ms
[DEBUG] Before importing data to content_text
10 seconds markup
10 seconds markup
10 seconds markup
10 seconds markup
10 seconds markup
10 seconds markup
[DEBUG] Chunk received: 704 bytes, Total received: 704 bytes
[DEBUG] Timeout: Exceeded max read duration.
[DEBUG] Total read time: 75360 ms
[DEBUG] Before json.loads

Server json:
{'here was already a parsed server response in json format'}

Response time:  79200 ms

As you can see, the device waited 60-70 seconds to execute socket.read(4096). So something must have been blocking the socket and this caused such a long delay in processing the response.

I would add that when I send the Connection: close header there is absolutely no problem with reading data from the socket.

My question is what could be causing this socket to block and am I even able to handle keep-alive POST requests in MicroPython? And if not, is there any other way of communicating with the server so that it is practically instant (I would expect the communication speed to stabilise and go below 1000ms, and preferably as quick as possible).

Thank you in advance for your feedback.

[mendenm]

shouldn't the read_full_response() be used with a socket with a fairly short (or zero) timeout, so it gets the end quickly?

[peetery]

Ok, I figured out that socket.read() won't execute until the socket is closed - that's why about 70 seconds pass because eventually the server closes the connections and only then am I able to read data from the socket. Is there any way to read data from the socket while the connection is still open? According to the keep-alive logic, I doesn't want to close it.

[peetery]

I cannot use recv() method because SSLSocket object has no that attribute. Any other ideas?

[karfas]

Use the Content-Length header value of the response (you are already parsing the response headers, I think) and read only the number of bytes given by Content-Length.

[peetery]

I had to set socket.setblocking(False) before doing wrap_socket and then everything started working perfectly fine. I also had to make a loop when reading status line from socket until it was read correctly (sometimes trying to read was faster than anything appeared on the socket?) Thanks for your help!