gcoap server breaks or becomes very unresponsive (sock_async related?)

[MichelRottleuthner]

Description

I'm having trouble with gcoap becoming completely unresponsive/unreliable in my application.
Up to the point where it doesn't reply to any message while the rest of the system (like shell, interrupts, other drivers etc.) seems to work fine.
First it was hard to reproduce as the node (an ESP32 in this case) just randomly didn't respond after some time even without heavy load.

Steps to reproduce the issue

Stressing the node with CoAP packets seems to work fine to reproduce it.
I'm not 100% sure yet if this is caused by the exact same problem that my other application is facing after some minutes or hours of uptime but in both cases the node behaves in the exact same way after it happend.
Terminal 1:

sudo dist/tools/tapsetup/tapsetup -c 1
BOARD=native make -C examples/gcoap clean all term

Maybe a bit overkill but works for me:
Terminal 2:

for i in {1..100}; \
do \
coap-client -m put coap://[riotlladdr%tapbr0]/cli/stats -e 123 &; \
done

Bisecting gave me ea62734 as the first bad commit that reproduces the problem. Maybe @kb2ma and @miri64 got some ideas?

Expected results

It might take some time to run thru the above loop but it works in a reliable fashion.
With git checkout ea62734baf25a678fa72da40351bf26dae2822e4~1 it does exactly that with no problem at all. Even with the above loop running to 10000 everything worked fine for me.

Actual results

On master the "done" outputs of the individual coap-client executions slows down at some point (the RIOT node gives some "gnrc_sock: dropped message to 0x5659bff0 (was full)" messages, and after it settled a bit, nothing happens anymore. I.e.: there are no COAP replies to the host anymore.
One could argue "yeah, heavy overload situation, unresponsiveness can be expected".
The real problem is that it never seems to recover from that.
Even after minutes of waiting, a manual coap-client -m get coap://[riotlladdr%tapbr0]/cli/stats/cli/stats isn't successful.

Versions

Happens with my native toolchain as well as with BUILD_IN_DOCKER=1.

[kb2ma]

Thanks for the simple test case, @MichelRottleuthner. I will try to reproduce and find the sticking point.

[kb2ma]

The issue is that gcoap does not drain all of the messages in the event queue. I was able to workaround the problem in 0112f04 in my gcoap/fix_sock_evt_race branch. The workaround iterates on the call to sock_udp_recv() within the sock event handler rather than calling it only once.

I was able to run 10k iterations of the CoAP request. Occasionally I saw the gnrc_sock warning about a dropped message, but gcoap remained responsive afterwards.

@miri64: My guess is that the UDP layer receives another message before the gcoap sock event handler returns, and a sock event is not generated in this case. Is this workaround the best solution?

I usually was able to see the issue when sending only five CoAP requests from the transcript above. After running the PUTs, wait a couple of seconds and try a GET like:

   coap-client -m get -T 5a -U coap://[fd00:bbbb::2]/cli/stats

The sock event triggered on this request pushes the stuck message from one of the earlier PUTs.

[MichelRottleuthner]

Thanks a lot @kb2ma!
I confirm that the fix solves the problem with gcoap becoming unresponsive. I also didn't see any stuck messages being pushed out with delay anymore.
I'll also test this fix in my other application I mentioned where the COAP endpoint became unresponsive just after some time even without heavy load.

I bet @miri64 knows better than me if this workaround is the best solution.
If the implementation of the UDP layer behaves like you describe, then even with iterating and draining the whole queue within the callback this won't be completely solved. There would still be the racy case where a new UDP message arrives just before returning from the handler, but after the decision was made to return. Wouldn't that imply the UDP layer must ensure firing another event if there is still data left after the callback returned?
The while-condition in your fix (while (type & SOCK_ASYNC_MSG_RECV)) looks a bit strange to me. The type is handed by value and not updated within the loop, right?. Shouldn't it depend on whether there is still data available from the sock, or something like that?

[kb2ma]

There would still be the racy case where a new UDP message arrives just before returning from the handler, but after the decision was made to return. Wouldn't that imply the UDP layer must ensure firing another event if there is still data left after the callback returned?

Good observation. I didn't identify exactly the how the producer/consumer interaction causes the backup. I expect @miri64 will have the insight to point us in the right direction.

The while-condition in your fix (while (type & SOCK_ASYNC_MSG_RECV)) looks a bit strange to me.

I agree it's not idiomatic. ;-) I basically was just combining the while loop into the event type conditional as an optimization to save a statement. The handler does not react to any other event types. At least a short comment would be good to explain.

[miri64]

Hi, other than the CoAP messages themselves, the sock should not signal any other UDP messages. It might indeed however be, that there is more than one CoAP message hidden behind the RECV signal. @MichelRottleuthner is right in his observation, that this should trigger another RECV after the previous is handled. This is however not the case, and should rather be fixed, than with the workaround you proposed. Could you check if

diff --git a/sys/net/gnrc/sock/gnrc_sock.c b/sys/net/gnrc/sock/gnrc_sock.c
index a1c22d77f..c6d0c2181 100644
--- a/sys/net/gnrc/sock/gnrc_sock.c
+++ b/sys/net/gnrc/sock/gnrc_sock.c
@@ -150,6 +150,11 @@ ssize_t gnrc_sock_recv(gnrc_sock_reg_t *reg, gnrc_pktsnip_t **pkt_out,
     }
     *pkt_out = pkt; /* set out parameter */
 
+#if IS_ACTIVE(SOCK_HAS_ASYNC)
+    if (reg->async_cb.generic && cib_avail(&reg->mbox.cib)) {
+        reg->async_cb.generic(reg, SOCK_ASYNC_MSG_RECV, reg->async_cb_arg);
+    }
+#endif
 #ifdef MODULE_FUZZING
     prevpkt = pkt;
 #endif

fixes this?

[MichelRottleuthner]

Yep it fixes it 👍

[miri64]

Then see #14059.

[miri64]

And #14060 for lwIP.