Repeated socket failures after ENOTCONN

[anecdata]

FeatherS2 with ESP32S2
6.2.0-beta.0 on 2021-01-22
adafruit-circuitpython-bundle-6.x-mpy-20210122

This is intermittent, so it's hard to demonstrate, but after only two of these errors (I would have expected the threshold to be four) mixed among successful HTTPS GETs:

Traceback (most recent call last):
  File "code.py", line 621, in http_get
  File "adafruit_requests.py", line 595, in get
  File "adafruit_requests.py", line 564, in request
  File "adafruit_requests.py", line 562, in request
  File "adafruit_requests.py", line 477, in _send_request
  File "adafruit_requests.py", line 468, in _send
  File "adafruit_requests.py", line 466, in _send
OSError: [Errno 128] ENOTCONN

all subsequent GET attempts yield:

Traceback (most recent call last):
  File "code.py", line 621, in http_get
  File "adafruit_requests.py", line 595, in get
  File "adafruit_requests.py", line 559, in request
  File "adafruit_requests.py", line 454, in _get_socket
RuntimeError: Repeated socket failures

ENOTCONN arises quickly, <0.005 seconds after the GET.

Only workaround found so far is to reload.

[jerryneedell]

@anecdata Do you have a time.sleep() in your code? see adafruit/circuitpython#4061

[hierophect]

@anecdata how rapidly are you making the send calls? I recently did some work to make the internals of Socket non-blocking, which might have resulted in some mis-identified errors if calls were made too fast. I'm still wrangling a bit with the error conventions of the Socket module, so I'm afraid I'm not sure how to go about addressing this problem without further info.

[tannewt]

Maybe Requests isn't catching the ENOTCONN and needs to try and recreate the socket as a result.

[anecdata]

@jerryneedell @hierophect There are no time.sleep() calls in the main loop of my 'production' code. When it starts up, there are two GET requests somewhat in sequence (5-10 seconds apart), but after that, it's minutes between GET requests. The ENOTCONN has arisen even after successful startup sequence, seemingly randomly in later loops, and after any two ENOTCONN it's out of business until reload. I'll try to gather more data.

[anecdata]

Just a small tidbit of information... I put some code in before every network action that tests for connection by checking wifi.radio.ipv4_address (and connects if necessary). wifi.radio.ipv4_address should be None after a connection drops, it's the best check I've found to passively test connection to the AP without risking an exception (e.g., wifi.radio.ap_info.).

Looks like when I get ENOTCONN either time, the connection still shows as active right before the GET:

Connected? True
Traceback (most recent call last):
  File "code.py", line 639, in http_get
  File "adafruit_requests.py", line 595, in get
  File "adafruit_requests.py", line 564, in request
  File "adafruit_requests.py", line 562, in request
  File "adafruit_requests.py", line 477, in _send_request
  File "adafruit_requests.py", line 468, in _send
  File "adafruit_requests.py", line 466, in _send
OSError: [Errno 128] ENOTCONN
Try GET #2 timeout 2s...
Connected? True
2021-01-26T11:08:04-06:00 200 bytearray(b'OK') 1.385s

[hierophect]

@anecdata as noted in the other thread, this is almost certainly related to Send() erroneously reporting this error as ENOTCONN and is actually probably a non blocking or other timing problem. I'd be updating in that other thread as I work on it since I don't think it has anything to do with Requests.

[anecdata]

@hierophect OK, thanks, just ruling out disconnection. I have a row of FeatherS2 boards with 6.1, 6.2, etc. so testing changes will be easy.

[hierophect]

@anecdata great, thanks a bunch for helping out with all this. Proper error handling and socket closing is still my biggest struggle on the low level.

[anecdata]

Behavior is changed, but still present. Using today's artifacts from #4049 commits (6.2.0-beta.1-29-gaf92db28b on 2021-02-01) on multiple FeatherS2 with ESP32S2, I get this intermittently after some successful GETs:

Traceback (most recent call last):
  File "code.py", line 638, in http_get
  File "adafruit_requests.py", line 595, in get
  File "adafruit_requests.py", line 564, in request
  File "adafruit_requests.py", line 562, in request
  File "adafruit_requests.py", line 477, in _send_request
  File "adafruit_requests.py", line 468, in _send
  File "adafruit_requests.py", line 466, in _send
OSError: Failed SSL handshake

Then, after any two of those (successful GETs in between):

Traceback (most recent call last):
  File "code.py", line 638, in http_get
  File "adafruit_requests.py", line 595, in get
  File "adafruit_requests.py", line 559, in request
  File "adafruit_requests.py", line 436, in _get_socket
  File "adafruit_requests.py", line 433, in _get_socket
RuntimeError: Out of sockets

[hierophect]

I would need to see your code to debug this any further. Based on the other issue, SSL failure can occur due to a timeout, but potentially from other problems as well. Running out of sockets will happen anytime you do not close a socket properly. I can track where these occur with LWIP_DEBUG and mp_printf/gdb but I'd need my hands on the code, or a subset of it that makes the issue occur (I don't get it with jerryn's anymore). My own test scripts also don't produce errors.

[hierophect]

Note that we haven't fixed Requests yet, which doesn't properly close the socket unless you make the modifications I discussed in the other thread, so maybe the out of sockets problem related to that?

[anecdata]

@hierophect Can you please point to the Requests modification you're referring to? I'm tracking about 20 networking issues and PRs right now, and I'm drawing a blank.

I'll try to get a minimal example to demo this issue.