"failed to send" & "No sockets available" exceptions with transfer-encoding:chunked using 20200918 Requests

[anecdata]

This does seem to be a distinct issue. The typical simpletest URLs all have a content-length header, but with a URL using {'transfer-encoding': 'chunked'} header in the legacy API, Requests will get Failed to send {num} bytes (sent 0) every other time (alternating), and on the 21st loop will get No sockets available thereafter.

CONFIG_LWIP_MAX_SOCKETS=10 in https://github.com/adafruit/nina-fw/blob/master/sdkconfig), and sockets become available again with esp.reset(), so those clues point to the socket not getting closed.

The odd loops work fine and return quickly. The even loops seem to use the full timeout before returning with the Failed to send... exception. I haven't found why the code does this alternating pattern, seems to indicate something not being (de)init, and may just be the socket not getting closed on alternate iterations because {mystery} reasons.

Tested on: Adafruit Feather M4 Express with samd51j19 CircuitPython 5.3.1 on 2020-07-13 and 6.0.0-alpha.3 on 2020-08-28 CircuitPython Library Bundle 6.x-mpy-20200918 and https://github.com/adafruit/Adafruit_CircuitPython_Requests/pull/33

Test code snippet:

loop = 1
while True:
    print("Fetching text...")  # from %s" % CHUNKED_URL)
    try:
        print(loop, end=" ")
        response = requests.get(CHUNKED_URL, timeout=5)
        # print(response.content)
        print(response.status_code, end=" ")
        print(response.reason, end=" ")
        print(response.headers)

        print(response.text)
        response.close()
    except (AttributeError) as e:
        print("AttributeError:", e)
    except (RuntimeError) as e:
        print("RuntimeError:", e)
        if "No sockets available" in repr(e):
            continue
            # esp.reset()
            # esp.connect_AP(secrets["ssid"], secrets["password"])
    time.sleep(1)
    print()
    loop += 1

Also, if response.text is not accessed, the second loop will result in:

Fetching text...
2 Traceback (most recent call last):
  File "code.py", line 108, in <module>
  File "code.py", line 98, in <module>
  File "/lib/adafruit_requests.py", line 605, in get
  File "/lib/adafruit_requests.py", line 475, in request
  File "/lib/adafruit_requests.py", line 252, in close
TypeError: unsupported types for __gt__: 'NoneType', 'int'

Seems _remaining doesn't get set after its initialization to None in that execution path.

[tannewt]

@anecdata could you post the full example minus your wifi credentials? I'm not sure what your chunked url example is.

[anecdata]

I had to make my own since it's hard to find one with a search engine. This one will return chunked to HTTP/1.1 request: https://anecdata.dev/ada/chunked/

[anecdata]

Adafruit PyPortal with samd51j20 6.0.0-beta.0 on 2020-09-21 adafruit-circuitpython-bundle-6.x-mpy-20200925 # latest released Requests

There's another chunked behavior that I didn't see until running for a longer time:

Traceback (most recent call last):
  File "code.py", line 60, in <module>
  File "adafruit_requests.py", line 632, in get
  File "adafruit_requests.py", line 532, in request
  File "adafruit_requests.py", line 257, in close
ValueError: invalid syntax for integer with base 16

It does this even with code that resets the ESP32 and re-connects to the AP prior to every request. After some iterations, invalid syntax for integer with base 16 occurs, then occurs on every request thereafter. It may be correlated to happening after a RuntimeError: Timed out waiting for SPI char occurs, but due to the reset and re-connect, it seems to be a Requests state that affects chunk_header.

Full code:

import board
import busio
from digitalio import DigitalInOut
import adafruit_esp32spi.adafruit_esp32spi_socket as socket
from adafruit_esp32spi import adafruit_esp32spi
import adafruit_requests as requests
import time
import os
import sys

from secrets import secrets

def connect():
    print(time.monotonic(), "Connecting to AP...", end=" ")
    while not esp.is_connected:
        try:
            esp.connect_AP(secrets["ssid"], secrets["password"])
        except RuntimeError as e:
            print("could not connect to AP, retrying: ", e)
            continue
    print("Connected")  #  to", str(esp.ssid, "utf-8"), "\tRSSI:", esp.rssi)

esp32_cs = DigitalInOut(board.ESP_CS)
esp32_ready = DigitalInOut(board.ESP_BUSY)
esp32_reset = DigitalInOut(board.ESP_RESET)

spi = busio.SPI(board.SCK, board.MOSI, board.MISO)
esp = adafruit_esp32spi.ESP_SPIcontrol(spi, esp32_cs, esp32_ready, esp32_reset)

# print test environment
print(os.uname().machine)
print(os.uname().version)
for _ in os.listdir():
    if "-bundle-" in _:
        print(_)

# legacy api
requests.set_socket(socket, esp)

# or choose your own chunked adventure...
CHUNKED_URL = "https://anecdata.dev/ada/chunked/"

loop = 1
while True:
    print(loop)
    print(time.monotonic(), "Fetching text...")
    try:
        # reset the ESP32
        esp.reset()
        time.sleep(1)

        # re-connect to AP
        connect()
        time.sleep(1)

        # even iterations will get:
        # RuntimeError: Failed to send 3 bytes (sent 0)
        # odd iterations will work, until TypeError
        response = requests.get(CHUNKED_URL, timeout=10)
        # print(response.content)
        print(time.monotonic(), response.status_code, response.reason)
        print(time.monotonic(), response.headers)

        # if response.text is not read, error occurs:
        # TypeError: unsupported types for __gt__: 'NoneType', 'int'
        _ = response.text
        # response.close()
    except (RuntimeError, AttributeError, ValueError) as e:
        sys.print_exception(e)
    time.sleep(15)
    loop += 1

[tannewt]

@anecdata can you modify requests to print out the string it's trying to parse? That may give us a clue.

[anecdata]

bytearray(b'')

I think it may be the RuntimeError: Timed out waiting for SPI char on the prior line (chunk_header = self._readto(b";", b"\r\n")) that kicks off this behavior... can't close the _last_response since it wasn't successful? Not clear how it then sticks in this mode.

I'll try a few things to see if I can get more useful data.

[tannewt]

@anecdata sounds like it's just not handling the socket being closed when trying to close it. :-)

[anecdata]

Adafruit PyPortal with samd51j20
6.0.0-rc.0 on 2020-10-16
adafruit-circuitpython-bundle-6.x-mpy-20201029, but with newer ESP32SPI 3.5.2 and newer Requests 1.7.3

Not sure if this is expected or not, but still seeing RuntimeError: Failed to send 3 bytes (sent 0) on alternating request iterations with {'transfer-encoding': 'chunked'} header.

However, all request iterations do return immediately rather than after the timeout expires, regardless of whether the request succeeds or gets the RuntImeError.

Addendum: just for cleanliness, same result when tested with:

Adafruit PyPortal with samd51j20
6.0.0-rc.0 on 2020-10-16
adafruit-circuitpython-bundle-6.x-mpy-20201030 (includes ESP32SPI 3.5.2 and Requests 1.7.3)

[ladyada]

the initial bug is fixed, can you try the latest version we have released?

[anecdata]

Still seeing RuntimeError: Failed to send 3 bytes (sent 0) on alternating request iterations with {'transfer-encoding': 'chunked'} header:

Adafruit PyPortal with samd51j20
6.0.0-rc.0 on 2020-10-16
adafruit-circuitpython-bundle-6.x-mpy-20201030 (includes ESP32SPI 3.5.2)
Requests 1.7.4 instead of Requests 1.7.3 from the bundle)

Full trace:

Traceback (most recent call last):
  File "code.py", line 64, in <module>
  File "/lib/adafruit_requests.py", line 636, in get
  File "/lib/adafruit_requests.py", line 540, in request
  File "/lib/adafruit_requests.py", line 537, in request
  File "/lib/adafruit_requests.py", line 458, in _send_request
  File "/lib/adafruit_requests.py", line 449, in _send
  File "adafruit_esp32spi/adafruit_esp32spi_socket.py", line 82, in send
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 710, in socket_write
RuntimeError: Failed to send 3 bytes (sent 0)

[brentru]

Seeing same as @anecdata using code from the Matrix Scroller, https://learn.adafruit.com/matrix-portal-new-guide-scroller/code-the-matrix-portal

URL it's trying to obtain: https://learn.adafruit.com/api/guides/new.json?count=5

obtaining time from adafruit.io server...
Getting time for timezone America/New_York
Socket missing recv_into. Using more memory to be compatible
New Hour, fetching new data...
Retrieving data...Traceback (most recent call last):
  File "code.py", line 99, in <module>
  File "/lib/adafruit_matrixportal/network.py", line 393, in fetch
  File "adafruit_requests.py", line 636, in get
  File "adafruit_requests.py", line 540, in request
  File "adafruit_requests.py", line 537, in request
  File "adafruit_requests.py", line 458, in _send_request
  File "adafruit_requests.py", line 449, in _send
  File "adafruit_esp32spi/adafruit_esp32spi_socket.py", line 82, in send
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 710, in socket_write
RuntimeError: Failed to send 3 bytes (sent 0)

[makermelissa]

Thanks for testing. Yeah, there were multiple problems and we're still fixing. I'm working on the above mentioned issue next, which is what #41 is about.

[anecdata]

I don't get any errors with @brentru's URL, but then I'm not doing any JSON processing. Maybe the difference yields a clue.

My current full test code (modified simpletest.py):

# adafruit_requests usage with an esp32spi_socket
import sys
import gc
import board
import busio
from digitalio import DigitalInOut
import time
import adafruit_esp32spi.adafruit_esp32spi_socket as socket
from adafruit_esp32spi import adafruit_esp32spi
import adafruit_requests as requests

def connect():
    print("Connecting to AP...", end=" ")
    while not esp.is_connected:
        try:
            esp.connect_AP(secrets["ssid"], secrets["password"])
        except RuntimeError as e:
            print("could not connect to AP, retrying: ", e)
            continue
    print(str(esp.ssid, "utf-8"), esp.rssi)

# Add a secrets.py to your filesystem that has a dictionary called secrets with "ssid" and
# "password" keys with your WiFi credentials. DO NOT share that file or commit it into Git or other
# source control.
# pylint: disable=no-name-in-module,wrong-import-order
try:
    from secrets import secrets
except ImportError:
    print("WiFi secrets are kept in secrets.py, please add them there!")
    raise

# If you are using a board with pre-defined ESP32 Pins:
esp32_cs = DigitalInOut(board.ESP_CS)
esp32_ready = DigitalInOut(board.ESP_BUSY)
esp32_reset = DigitalInOut(board.ESP_RESET)

# If you have an externally connected ESP32:
# esp32_cs = DigitalInOut(board.D9)
# esp32_ready = DigitalInOut(board.D10)
# esp32_reset = DigitalInOut(board.D5)

spi = busio.SPI(board.SCK, board.MOSI, board.MISO)
esp = adafruit_esp32spi.ESP_SPIcontrol(spi, esp32_cs, esp32_ready, esp32_reset)

connect()

# Initialize a requests object with a socket and esp32spi interface
# socket.set_interface(esp)
# requests.set_socket(socket)
#
# Requests (legacy API)
requests.set_socket(socket, esp)

# Choose your own chunked adventure...
CHUNKED_URL = "https://anecdata.dev/ada/chunked/"
# CHUNKED_URL = "https://learn.adafruit.com/api/guides/new.json?count=5"

loop = 1
while True:
    print(loop, "Fetching text...")
    try:
        response = requests.get(CHUNKED_URL, timeout=15)
        print(response.status_code, end=" ")
        print(response.reason, end=" ")
        print(response.headers)
        print(response.text)
        response.close()
    except (RuntimeError) as e:
        # RuntimeError: Failed to send 3 bytes (sent 0)
        sys.print_exception(e)
        try:
            response.close()
        except (ValueError, NameError, AttributeError) as e:
            sys.print_exception(e)
            print("Reset ESP...", esp.reset())
            connect()

    time.sleep(1)
    print()
    loop += 1

P.S. If I should be putting full code listings in a gist instead of here, just say the word.

[tannewt]

@anecdata Can you print out the headers of the request that succeeds? I suspect it includes a "Connection: close" header.

[anecdata]

Output from above code (1st succeeds, then trace from failed, followed by success output):

1 ...{snip}...

2 Fetching text...
Traceback (most recent call last):
  File "code.py", line 64, in <module>
  File "/lib/adafruit_requests.py", line 636, in get
  File "/lib/adafruit_requests.py", line 540, in request
  File "/lib/adafruit_requests.py", line 537, in request
  File "/lib/adafruit_requests.py", line 458, in _send_request
  File "/lib/adafruit_requests.py", line 449, in _send
  File "adafruit_esp32spi/adafruit_esp32spi_socket.py", line 82, in send
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 710, in socket_write
RuntimeError: Failed to send 3 bytes (sent 0)

3 Fetching text...
Socket missing recv_into. Using more memory to be compatible
200 bytearray(b'OK') {'Transfer-Encoding': 'chunked', 'Date': 'Fri, 30 Oct 2020 18:49:51 GMT', 'Server': 'Apache', 'Connection': 'Upgrade', 'Vary': 'Accept-Encoding,User-Agent', 'Upgrade': 'h2', 'Content-Type': 'text/plain;charset=UTF-8'}

[anecdata]

Terminating chunk should be zero-length? There are no headers indicating trailers. Then there should be a final CRLF:

0\r\n\r\n

Like that, I believe, after the non-empty content chunks. Is that last \r\n getting drained (does it matter)?

[tannewt]

@anecdata Ya, that looks correct to me. You do want it drained so it isn't read with the next request.

[anecdata]

I'm seeing well-behaved chunked response handling using:

Adafruit PyPortal with samd51j20
6.0.0-rc.1 on 2020-11-03
adafruit-circuitpython-bundle-6.x-mpy-20201107 (with ESP32SPI 3.5.3 + Requests 1.7.5)

Will continue to test, probably close soon.

[anecdata]

Well-behaved chunked response handling on rc.2 with 20201111 libraries. Closing.