Crashing when operating as a server

[dannystaple]

When the ESP32 is used as a server (by CircuitPython, tested on RP2040), it will consistently crash after a few hundred requests.

I have narrowed this to being in the NINA-FW and not CircuitPython ESP32SPI libraries, although these were used for testing.

Reproducing case

The code for testing this is in the draft pull request:
adafruit/Adafruit_CircuitPython_ESP32SPI#168. Note this PR builds on the branch I made with changes to error handling.

On the Raspberry Pi Pico (or CircuitPython device), use examples/stress_tests/socket_client_server_stress/esp_rp2040_server/cp_socket_count_server.py. Adapt pin configuration to suit.

On a suitable PC, with Python3, in examples/stress_tests/socket_client_server_stress/pc_client/pc_socket_count_client.py, correct the HOST variable to match the location the CircuitPython device reported. Then launch the client.

It will run for a few minutes, producing a count. Eventually, and reproducibly, it will stop with an exception due to failing to communicate with the ESP32.

Sending 325
checking if last client sock still valid
client sock num is:  1
Sending 326
checking if last client sock still valid
Traceback (most recent call last):
  File "<stdin>", line 122, in <module>
  File "<stdin>", line 109, in run
  File "<stdin>", line 85, in client_available
  File "/lib/adafruit_esp32spi/adafruit_esp32spi.py", line 776, in socket_available
  File "/lib/adafruit_esp32spi/adafruit_esp32spi.py", line 332, in _send_command_get_response
  File "/lib/adafruit_esp32spi/adafruit_esp32spi.py", line 288, in _wait_response_cmd
  File "/lib/adafruit_esp32spi/adafruit_esp32spi.py", line 197, in _wait_for_ready
TimeoutError: ESP32 not responding

The count may vary, but it will eventually always end up here. CircuitPython code can only continue by resetting the esp32 and reconnecting to wifi.

Narrowing the cause

Although this started with an ESP32 Airlift module, a USB enabled ESP32 vroom module was easier to debug/flash firmware to try get closer to the issue.

I used a bare ESP32 and built/flashed the firmware with the DEBUG enabled. This bare ESP32 allowed me to connect via USB so I could easily flash it, and monitor it. I ran the above example again, but also capturing serial from the esp32 (using python3 -m serial.tools.miniterm /dev/cu.SLAB_USBtoUART 115200 | tee serial.log so I could tee into a file, this is from Pyserial).

When running the code, I could see it eventually died at the same location:

RESPONSE: e0ab0102ff00ee
.8COMMAND: e02b010100ee0004
RESPONSE: e0ab0102ff00ee
.8COMMAND: e02b010100ee0004
RESPONSE: e0ab0102ff00ee
.8COMMAND: e02b010100ee0004

Decoding these commands,2b is _AVAIL_DATA_TCP_CMD, which maps to the availDataTcp method in CommandHandler.cpp.

I then instrumented this, specifically around server socket handling with more debug to see if I could further narrow the issue.
The instrumentation is in #45.

With this instrumentation I see:

.8COMMAND: e02b010100ee0004
Handling availDataTcpSocket type is 0Socket is a tcpServerCopying data rb

(Yes, it could do with newlines, but there is so much debug, I left it on one line)
Note that the "rb" characters are in the middle of the copying data debug output.

Another time I also saw:

.8COMMAND: e02b010100ee0004
Handling availDataTcpSocket type is 0Socket is a tcpServer

It never got to copying data. I am concerned that the bug is asynchronous - but it is always around this area I see this crash. Any help would be much appreciated.