Slow GET response times using v1.7.2 of adafruit_requests

[DeanDavis]

This is a cross-post from the forum site but after experimenting more, this is either a hardware issue or an issue with the adafruit_requests library.
The quick version is that it's taking over a minute to get a response from some URLs using adafruit_requests and this is not an issue of the server side.

First Hardware:
Adafruit Matrix Portal running 6.0.0rc0 CircuitPython
ESP32 updated to firmware 1.7.1
WiFi SSID RSSI is 67 on connection

Testing method:
Used this code for basic test
https://github.com/adafruit/Adafruit_CircuitPython_ESP32SPI/blob/master/examples/esp32spi_simpletest.py
Ran this code using library adafruit_requests v1.7.2
Running the code as is results in successful test. Everything seems to be responsive.

But if I switch that code's "JSON_URL" from the one supplied to a URL I'm interested in
MLB Game Results
It takes over a minute (and sometimes outright fails) to return data.
This URL returns data instantly in a browser or using a tool like Postman.

Also, the call to requests.get (seen below) does return immediately.
In the code block below (taken and modified from the example) the status code is printed immediately.
The minute long pause in the code comes at the r.json() call

print("Fetching json from", JSON_URL)
r = requests.get(JSON_URL)
print("-" * 40)
print("Status Code {}".format(r.status_code))
print(r.json())
print("-" * 40)

[anecdata]

Likely the same or similar issue as #34 The MLB URL has a Transfer-Encoding: chunked header.

The content isn't actually fetched at the get, it's fetched at the r.json().

[tannewt]

I think the core of the problem is that I switched from fetching the whole string and then parsing (in <1.7.0) to fetching characters as needed for parsing. The ESP32SPI library isn't optimized for this so it's quite slow. The benefit is that the largest allocation is much smaller because it's only for the largest individual json element, not the whole string.

I have an improved version of ESP32SPI here but it's not well tested: https://github.com/tannewt/Adafruit_CircuitPython_ESP32SPI/tree/split

[makermelissa]

@tannewt I thought I would give your ESP32SPI a test in case it fixed some issues, but it fails at one of the imports: https://github.com/tannewt/Adafruit_CircuitPython_ESP32SPI/blob/split/adafruit_esp32spi/adafruit_esp32spi_wifimanager.py#L19

[DeanDavis]

I do think there is an issue in the adafruit_requests library. I've been tracing it for a couple of hours now and think I'm close to a solution. I'm pretty sure the issue is either a bug in the "while true" loop of the _readto method
or my URL's response is malformed or a combination of both.

I can tell you from my testing that the data from the response is immediately available to the results class. This is why I doubt it's ultimately an issue with the ESP32SPI library.

With a little more testing I should have a conclusion and a solution later tonight or tomorrow.

[makermelissa]

Awesome, thank you. I'd be happy to test it out.

[DeanDavis]

Finished my trace and I've narrowed down the issue. Unfortunately my hypothesis of it being a bug in adafruit_requests turns out not to be the case.

The URL I'm testing with returns application/json data chunked and in gzip format. The server is sending properly formatted chunked data.

It's in two chunks. The first is 654 bytes and the second is the terminating chunk of 0 bytes. This is after some lower level code has unzipped the response data.

Here's what I figured out.
The GET call is made and returns very quickly. The request is initialized and the status code and headers parsed.
Then I make a call to the .text method (doesn't matter if the call is to .text or .content).

.text does a looped call to _readinto
On the first loop through _readinto grabs the length of the first chunk, 654 then keeps looping grabbing those next 654 bytes by calling _recv_into until 654 bytes have been read. That's all good. Very quick.

So now, after grabbing that first chunk of 654 bytes the next call into _readinto will want to start getting the next chunk.
First thing it does is throw away 2 bytes (\r\n) since those are the terminating bytes of the previous chunk and not needed and not counted in the 654.

This is where things go wrong.
Now, in this case the next chunk is just the terminating chunk so it should just be 5 bytes '0\r\n\r\n'
So next think to do is to grab the size of the next chunk by reading the characters up to the next instance of "\r\n"
The call is...
chunk_header = self._readto(b";", b"\r\n")
_readto is trying to return the bytes up to the '\r\n'
It first tries to look in the class property _receive_buffer but by this time that is empty. So all the code looking for the characters fails and we drop down to that tries to read more of the data from the socket by calling _recv_into
The call is read = self._recv_into(memoryview(buf)[end:])
This call should quickly return the last 5 bytes we need to complete the process. buf is a 160 bytearray and at this point end=0

(TL;DR - This is where the pause occurs)
So trace this into _recv_into and the pause comes at the line
b = self.socket.recv(size)
At this point size=160 since that's the size of the bytearray that was passed in.
This call stalls for over a minute. But once it does return b does contain the 5 bytes necessary and the rest of the program proceeds normally.

Before this specific point the requests code does call into _recv_info and thus self.socket.recv many many times.
It's only when getting the 2nd chunk or possibly the terminating chunk do we see this delay.

I haven't tested the code against a site that returns data in several chunks. I'll see if I can.
Also, in case this factors into it the data returned from my test URL is chunked and gzip uncoded. I know the code in socket must be doing the unzipping maybe the pause is an issue unzipping the terminating chuck.

I guess I'm willing to try and dive into the socket code but I'm hoping this helps someone with more experience in that code.

[DeanDavis]

Update.
gzip encoding from the server doesn't factor into this. I was able to get the server to send raw data, not gzipped, by using the "Accept-Encoding: identity" header.
Even with unzipped data the code still stalls on the b = self.socket.recv(size) call when trying to get the data for the second/terminating chunk.

[tannewt]

Hi @DeanDavis, thanks for the thorough investigation! This appears to be an issue with recv. The behavior should be that it only times out when no bytes are available from the start. If a fraction of the requested bytes are available, then they should be quickly returned. I've made a PR to fix ESP32SPI here: adafruit/Adafruit_CircuitPython_ESP32SPI#112

[tannewt]

It looks the CircuitPython ESP32-S2 core implementation has the same issue so I'll fix it there too.

[DeanDavis]

Just tested the new ESP32SPI library. Looks good. My issue was solved. Thanks.