Dead-Lock of async_tcp task and tcp/ip task when _async_queue fills up completely

[ul-gh]

Hi,

when using an AsyncEventSource instance on ESP32 platform, multiple issues arise due to multi-threaded access to the AsyncTCP event queue (_async_queue), the AsyncEventSource internal _messageQueue and locked usage of the LWIP callback API.

One of the issues was already adressed by Arjan Filius by adding mutex locking of access to the AsyncEventSource _messageQueue (see iafilius/ESPAsyncWebServer/commit/d924de1..)

On my AJAX API project, I tried above commit plus multiple other fixes, but after extensive tracing of heap memory issues etc in AsyncTCP and ESPAsyncWebServer when using the SSE event source, I ran into a dead-lock issue now which causes the async_tcp task watchdog timer rebooting the whole system.

As far as my observation is correct, the issue is that enabling the AsyncEventSource causes arbitrarily timed accesses of the AsyncTCP event queue from the LWIP tcp_ip task (by activating the LWIP _tcp_poll periodic callback and time-interleaved data arriving via the network/IP layer) while at the same time the LWIP API is called by the async_tcp task (sending responses) and also by the user application task calling the AsyncEventSource send() methods.(AsyncEventSourceClient::_queueMessage()... ultimately calling a AsyncClient "client->write()" call etc)

==> I recorded an example call trace using a hardware JTAG debugger, please see following attached PNG image:

For the application code triggering the issue, please excuse I did not yet prepare a minimum-code example yet, however please let me know if this would be helpful.

The relevant changes I made to ESPAsyncWebServer and AsyncTCP on the "dev" branches under:
https://github.com/ul-gh/ESPAsyncWebServer/tree/dev and:
https://github.com/ul-gh/AsyncTCP/tree/dev

The whole application using the ESPAsyncWebServer is:
https://github.com/ul-gh/esp_ajax_if

[ul-gh]

Looking further into this, I realise the dead-lock is just what happens when the _async_queue of the async_tcp event loop fills up 100%, causing xQueueGenericSend() to block indefinitely.

Anyways, the _async_queue filling up completely seems to happen easily when periodic push messages are sent via SSE / via the AsyncEventSource. I have to look more into the "why" that happens but I suspect any one of the default or user defined AsyncCallbackWebHandlers blocks for a certain amount of time while SSE push messages are acknowledged.

If this is correct, then there should be a graceful handling of the event loop filling to the top (e.g. a sensible error message plus discarding further events).

Also, what helps in my case is increasing the _async_queue length, which by default is only 32. (This could be a configure option)
I set this to 256 and indeed now I experience up to approx. 100 events queuing up from time to time, now finally without the dead-lock issue.

Please let me know if you need more input.

[BlueAndi]

You could measure in _handle_async_event() how long a event needs for handling, especially in case of LWIP_TCP_RECV. If there are peaks greater than 300 ms (as I see in your javascript), you could dig in there. Usually SPIFFS access needs quite long.

[ul-gh]

Thank you Andi, I did just that and the guess was correct.

I noticed blocking times of up to seven (!) seconds for some of the initial requests in the AsyncClient::_s_recv() handler.
And yes, ultimately I could trace it down to the AsyncStaticWebHandler doing some SPIFFS access. What happened was I had the wrong initialisation order for the AsyncWebHandlers where the static handler serving the root (/) URI was called first before the specialised API endpoint handlers. The massive timeouts happened downwards from the .canHandle() method of the AsyncStaticWebHandler wjich was for every API endpoint called first-in-line looking for any local SPIFFS file with the same name, which of course did not exist.

I did not go into more detail there, why the search for a nonexistent SPIFFS file could possibly cause a multi-second timeout - but at least the result is clear now. The event timer task was pushing SSE events for the whole massive timeout and the _async_queue was filling up.

So this needs to be fixed:

• If or when the async event queue fills up for whatever reason, this should not result in an infinite dead-lock of the tasks (This is a clear Denial-of-Service if a request is made for an invalid file name)

• There should be a warning or error in the log output when a queue overflow happens

• For the AsyncStaticWebHandler, if the massive delays are not caused by some bug or mis-configuration, (i.e. the SPIFFS just /is/ that slow, then it would help much if this was documented.

Also nice-to-have would be a configure option for the queue length, I guess.

I realize this is more than one issue here in one thread, but if this is appreciated, I can post individual issue numbers for these and maybe even provide a fix or two with a PR next week.

• Anyways, it would be nice to know from others if these issues can be confirmed or what else should be considered.

[ul-gh]

I need now to add, a lot of what is reported in issue #825 very much looks like the same issue.
See e.g. #825 (comment)

So fixing this will likely also fix #825.

[stale]

[STALE_SET] This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.

[ul-gh]

So although the original issue is the _async_queue filling up due to some SPIFFS or other time lag, it would be nice to know if there will by any official fix for this dead-lock issue.

[stale]

[STALE_CLR] This issue has been removed from the stale queue. Please ensure activity to keep it openin the future.

[brandonros]

How can I tell if #921 is this?

[ul-gh]

Hi Brandon,

you could try if the version from my fork fixes your issue:
https://github.com/ul-gh/ESPAsyncWebServer/

Regards,
Ulrich

[brandonros]

@ul-gh your fork seems to be equal with master?

[ul-gh]

That was fast reply..

Pardon me, there is a "dev" branch which combines the patches for #837, #884 and #888.
https://github.com/ul-gh/ESPAsyncWebServer/tree/dev