Stream receives packets/frames but never calls QUIC_STREAM_EVENT_RECEIVE

[Johan511]

I am building a publisher-subscriber application using MsQuic and noticed that sometimes the subscriber hangs because it is expecting data from the stream but never receives any.

Despite occurring quite frequently in the Release configuration, replicating the bug with QUIC_ENABLE_LOGGING was quite hard but it did occur after a couple hundred runs.

While going through the MsQuic logs it was evident that the publisher was sending packet and the subscriber is receiving these bytes too, but the stream never indicates the QUIC_STREAM_EVENT_RECEIVE event.

The logs has the following type of events

[strm][0x7f94200557c0] Processing frame in packet 8796093022242 [StreamReceiveFrame:/home/hhn/raven/raven/submodules/msquic/src/core/stream_recv.c:592]
Received 34 bytes, offset=7953 Ready=1 [Receive:/home/hhn/raven/raven/submodules/msquic/src/core/stream_recv.c:550]
[strm][0x7f94200557c0] Done processing frame [StreamReceiveFrameComplete:/home/hhn/raven/raven/submodules/msquic/src/core/stream_recv.c:722]

But does not have Indicating QUIC_STREAM_EVENT_RECEIVE events (barring a few at the start)
Does anyone have any insights on why this might be the case?

The complete log file is over 170k lines hence I am not attaching it now, I can attach it if required
Filtered log file containing logs related to the particular stream.

Log file was obtained using the following grep command
grep --text '\[strm\]\[0x7f94200557c0\]' $(input) > $(output)

Additional Observations:

1. On attaching gdb to the process it was observed that the MsQuic worker threads are in the epoll function
2. Program does not give any memory errors with ASAN
3. Program does have some errors with TSAN but they seem to be benign errors with functions such as eventFd or pipe, I can attach the TSAN error log if required

[nibanks]

A few guesses:

1. The worker thread for the connection is blocked or delayed by other work, possibly one of your callbacks.
2. If you're using async receives (and not multi-receive) you already have another receive pending.
3. You did a partial receive drain and didn't re-enable receives.

I will try to take a look at the log to see if I can narrow it down.

[nibanks]

Looking at the logs, it looks like there is a pending receive you haven't completed yet:

[strm][0x7f94200557c0] Allocated, Conn=0xeead390
[strm][0x7f94200557c0] Created, Conn=0xeead390 ID=3 IsLocal=0
[strm][0x7f94200557c0] Send State: 0
[strm][0x7f94200557c0] Recv State: 1

[strm][0x7f94200557c0] Indicating QUIC_STREAM_EVENT_RECEIVE [33 bytes, 1 buffers, 0x0 flags] 
[strm][0x7f94200557c0] Receive complete call [33 bytes] 
[strm][0x7f94200557c0] Receive complete [33 bytes] 

[strm][0x7f94200557c0] Indicating QUIC_STREAM_EVENT_RECEIVE [56 bytes, 1 buffers, 0x0 flags] 
[strm][0x7f94200557c0] Receive complete call [56 bytes] 
[strm][0x7f94200557c0] Receive complete [56 bytes] 

[strm][0x7f94200557c0] Indicating QUIC_STREAM_EVENT_RECEIVE [190 bytes, 1 buffers, 0x0 flags] 
<no receive complete events>

[Johan511]

The worker thread for the connection is blocked or delayed by other work, possibly one of your callbacks.

All worker threads are waiting on epoll, so I doubt this is the issue

If you're using async receives (and not multi-receive) you already have another receive pending.

My application does use async receive (returns QUIC_STATUS_PENDING on all receives), and does call StreamReceiveComplete after processing a bunch of QUIC_BUFFERs (buffers which can construct an object, which is around 15-20 bytes in size).
I will check if it's doing so, and also try enabling StreamMultiReceiveEnabled.

You did a partial receive drain and didn't re-enable receives.

Could be the case, let me set StreamReceiveSetEnabled and check it out

---

On a second look at the documentation, Multi Receive mode seems to be what I need for my application to run without any hiccups.

This seems to be disabled by default, is there any reason for this?

This changes internal receive buffer more efficient for continuous receiving.

The documentation does have this line about enabling MultiReceive being more performant for MsQuic. Is it disabled by default to make sure the application isn't overloaded with data while it's still processing pending data?

[nibanks]

This seems to be disabled by default, is there any reason for this?

Because it's a behavior change. Any behavior change is considered breaking, so we much make it opt-in to not break older clients that don't expect parallel receive events (while another is still outstanding).

[Johan511]

I have tried setting StreamReceiveSetEnabled(streamHandle, TRUE); but still face the same issue.

This is a snippet of my QUIC_STREAM_EVENT_RECEIVE callback for reference

        case QUIC_STREAM_EVENT_RECEIVE:
        {
            for (std::uint64_t i = 0; i < event->RECEIVE.BufferCount; i++)
            {
                // queue buffer into a different thread system to be consumed
            }
            StreamReceiveSetEnabled(streamHandle, true);
            return QUIC_STATUS_PENDING;
        }

Just to test it out, I have removed all calls to StreamReceiveComplete from my application, it still has calls to StreamReceiveSetEnabled in the stream callback; this leads to the same result where all streams stop indicating QUIC_STREAM_EVENT_RECEIVE on all executions of the program but, now it happens right after the first QUIC_STREAM_EVENT_RECEIVE instead of a random undetermined point of time.

There isn't much documentation about how StreamReceiveSetEnabled should be called, this seemed like a reasonable way to do it. I have also tried calling it on all stream events, it does not help either.

Have I understood StreamReceiveSetEnabled correctly?

I have observed that StreamReceiveSetEnabled queues an operation onto the stream's event queue, is it possible that because of the overwhelming number of sent events being received, this operation would never be executed? Fwiw, my publisher does send a finite number of messages (say around 20KB).

Filtered Log

---

When using MultiReceive, and there is a burst of QUIC_BUFFERs being received, is there a strict ordering of the QUIC_STREAM_EVENT_RECEIVE events called for each QUIC_BUFFER?

Over a stream if qb0 is ordered before qb1

Does MsQuic ensure that there is a strict happens before relationship between the QUIC_STREAM_EVENT_RECEIVE callback of qb0 finishing execution (returns any QUIC_STATUS) and the QUIC_STREAM_EVENT_RECEIVE callback of qb1 being called?

[nibanks]

No, you only need to use this API if you are doing partial receives. A partial receive pauses future callbacks until you re-enable. I think you just want multi-receive.

[Johan511]

If I choose not to call StreamReceiveComplete, shouldn't it be considered as a partial data acceptance of 0 bytes?

According to the documentation of multi-receive

Setting StreamMultiReceiveEnabled an app can continue getting indicated by QUIC_STREAM_EVENT_RECEIVE without returning QUIC_STATUS_SUCCESS nor calling StreamReceiveComplete.

Which as you mentioned seems to align with what I need

I have tried using multi-receive (and it does work even with no calls to StreamReceiveComplete as expected) but it causes errors in my deserialization module, I have a stream local queue which where QUIC_BUFFERs get queued to and a state machine which reads the buffers and dequeues them once a message is read and constructed. Dequeue calls a destruct on std::unique_ptr<>, which has a custom deleter that calls StreamReceiveComplete

On enabling multi-receive, this completely breaks in a manner which made me unsure about if the callbacks are called sequentially on the QUIC_BUFFERs

Hence I was curious about the callback execution order guarantees provided when StreamMultiReceiveEnabled is enabled.

[nibanks]

I think you need to investigate the issues you're having with multi-receive. That's likely your best path forward. The events are always serialized up to the app (for the entire connection), so I suspect there might be a bug on your side.

BTW, this is exactly why we don't enable these behavior changes by default. 😄 It can cause crashes in apps.

[Johan511]

Sure, I will try having a deeper look at my deserialization module at get back.

[Johan511]

Fwiw,

Following some debugging and off-github discussion with @nibanks

The reason for this bug appears to be that the lifetime of the QUIC_BUFFER object passed into the stream callback in case of a QUIC_STREAM_EVENT_RECEIVE is limited to the scope of the callback, returning QUIC_STATUS_PENDING only extends the lifetime of the underlying byte buffer until the application calls StreamReceiveComplete not of the QUIC_BUFFER object.