Reading msquic logs

[ManickaP]

I'm trying to debug incorrectly closed streams in msquic and I'm trying to make sense of the logs.

• I'm seeing stream addresses being reused, I assume there's pooling going on behind the scenes. Just to confirm, when I see: [strm][0x7f46cc04bc20] Destroyed it means the stream has been returned to the pool and this is the last message for that particular instance.
• [ api] Enter 19 (0x7f46cc04bc20). according to code 19 is stream close. This should be the last operation called on the stream.
• [strm][0x7f46cc04bc20] Indicating QUIC_STREAM_EVENT_SHUTDOWN_COMPLETE must be observed happen before the close is called. Otherwise, the stream will end up in bad state.

What is the expected behavior of msquic, when the stream is closed before QUIC_STREAM_EVENT_SHUTDOWN_COMPLETE arrives?

I understand this is an application error, which must be fixed. But I'm not observing any errors from msquic. What I'm also NOT observing is any new QUIC_CONNECTION_EVENT_PEER_STREAM_STARTED after the MAX_STREAMS has been reached. Thus, I'm left with hanging server side connection, waiting for new streams; and hanging HTTP/3 client waiting for the response. It all gets unblocked after a certain timeout, so it doesn't hang indefinitely.

[nibanks]

Bad things happen if you close without shutting down completely:

_IRQL_requires_max_(PASSIVE_LEVEL)
void
QuicStreamClose(
    _In_ __drv_freesMem(Mem) QUIC_STREAM* Stream
    )
{
    if (!Stream->Flags.ShutdownComplete) {

        if (Stream->Flags.Started) {
            //
            // TODO - If the stream hasn't been aborted already, then this is a
            // fatal error for the connection. The QUIC transport cannot "just
            // pick an error" to shutdown the stream with. It must abort the
            // entire connection.
            //
            QuicTraceLogStreamWarning(
                CloseWithoutShutdown,
                Stream,
                "Closing handle without fully shutting down");
        }

You trigger an implicit abort, BUT we don't have an error code to use for the abort! So we eventually just close with 0. 😢 Ideally, this should be a FATAL error and I kill the process, but I'm not sure I can practically do that...

[CarnaViire]

@nibanks could your PR possibly break again these scenarios? #1384

[nibanks]

If you ever shutdown the receive direction while you have a receive pending and we've already received the FIN from the peer, this could happen. So yes, in the case where you have a receive outstanding, then we receive the FIN, which gets queued, and then you call shutdown, this would get stuck. This PR will fix all instances of this behavior.

[CarnaViire]

I see, in the scenarios in the issue #1384 the receiving party just reads patiently, neither aborting reads, not closing the stream. So I guess we'll be OK there and the SHUTDOWN_COMPLETE will wait until we've read everything, right?

[nibanks]

If you wait until SHUTDOWN_COMPLETE you will be fine. The problem only comes if you prematurely abort the receive path after you've already actually received the FIN, but just not delivered it to the app.

[ManickaP]

So you still have a pending receive somewhere.

I was aware of that and that's been fixed in the app as well. It was manifesting as never receiving SHUTDOWN_COMPLETE and was easy to spot on the very first stream.