Open
Description
And because of that, we sometimes wrongly issue ABORT_READ.
The ABORT_READ is issued by MsQuicStream.Dispose method because of the ReadState is not in a final state (it didn't receive READ event with FIN flag yet).
This can be easily simulated with our HTTP stress tests, POST Duplex Slow operation (seen locally in 99.9% cases).
Moreover, according to the spec: https://www.ietf.org/archive/id/draft-ietf-quic-http-34.html#name-http-message-exchanges, only following sequence of frames is allowed:
- the header section, sent as a single HEADERS frame (see Section 7.2.2),
- optionally, the content, if present, sent as a series of DATA frames (see Section 7.2.1)
- optionally, the trailer section, if present, sent as a single HEADERS frame.
So in case server would send garbage after trailers, we should report an error: Receipt of an invalid sequence of frames MUST be treated as a connection error of type H3_FRAME_UNEXPECTED Probably even close the connection.
Note that we decided to ignore anything after trailers (I don't know the exact reason):
If we decide to fix this, I do not think we should hold and block HttpResponseMessage dispose on this though. We should probably try to drain the stream asynchronously after the trailing headers. Then make sure that we don't issue QuicStream.Dispose before the drain is complete (with some timeout to not to hang indefinitely).
Log analysis:
12:26:21
client 0x7FC0EC003720
server 0x7f130402d0e0
[12:26:21.664499][ api] Enter 21 (0x7fc0ec003720). - client shutdown send
[12:26:21.664614][strm][0x7f130402d0e0] Indicating QUIC_STREAM_EVENT_RECEIVE [0 bytes, 0 buffers, 0x2 flags] - server receive FIN flag
[12:26:21.664622][strm][0x7f130402d0e0] Indicating QUIC_STREAM_EVENT_PEER_SEND_SHUTDOWN - server peer send shutdown
[12:26:21.664719][strm][0x7fc0ec003720] Indicating QUIC_STREAM_EVENT_SEND_SHUTDOWN_COMPLETE - client send shutdown done
[12:26:21.664845][ api] Enter 22 (0x7f130402d0e0). - server sends trailers
[12:26:21.664911][strm][0x7fc0ec003720] Indicating QUIC_STREAM_EVENT_RECEIVE [21 bytes, 1 buffers, 0x0 flags] - client receives trailers
10:26:21.6649398[HandlerMessage] poolId: 1054474, workerId: 39785641, requestId: 4, memberName: ReadFrameEnvelopeAsync, message: Received frame 1 of length 19.
10:26:21.6649791[Info] thisOrContextObject: State#62474978, memberName: Dispose, message: [strm][0x7FC0EC003720] Stream disposing True state=[strm][0x7FC0EC003720] read=None, send=Finished, shutdownSend=Finished, shutdown=None
10:26:21.6649900[Info] thisOrContextObject: State#62474978, memberName: Dispose, message: [strm][0x7FC0EC003720] Stream disposing(callShutdown=True, abortRead=True, completeRead=False, releaseHandles=False) state=[strm][0x7FC0EC003720] read=Aborted, send=Finished, shutdownSend=Finished, shutdown=Pending
10:26:21.6650006[Info] thisOrContextObject: State#62474978, memberName: StartShutdown, message: [strm][0x7FC0EC003720] Stream StartShutdown flags=GRACEFUL error=0
10:26:21.6650125[Info] thisOrContextObject: State#62474978, memberName: StartShutdown, message: [strm][0x7FC0EC003720] Stream StartShutdown flags=ABORT_RECEIVE error=4294967295
[12:26:21.665005][ api] Enter 21 (0x7fc0ec003720). - client shutdown graceful
[12:26:21.665016][ api] Enter 21 (0x7fc0ec003720). - client abort read
10:26:21.6650232[Info] thisOrContextObject: State#62474978, memberName: Dispose, message: [strm][0x7FC0EC003720] Stream disposed state=[strm][0x7FC0EC003720] read=Aborted, send=Finished, shutdownSend=Finished, shutdown=Pending
10:26:21.6650917[Info] thisOrContextObject: (null), memberName: Operations, message: POST Duplex Slow --> StatusCode: 200, ReasonPhrase: 'OK', Version: 3.0, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
Date: Thu, 07 Oct 2021 10:26:21 GMT
Server: Kestrel
}, Trailing Headers:
{
crc32: 1204034434
}
[12:26:21.665101][strm][0x7f130402d0e0] Indicating QUIC_STREAM_EVENT_PEER_RECEIVE_ABORTED (0x4294967295) - server peer receive aborted
[12:26:21.665103][ api] Enter 21 (0x7f130402d0e0). - server shutdown send
[12:26:21.665745][strm][0x7fc0ec003720] Indicating QUIC_STREAM_EVENT_SHUTDOWN_COMPLETE [ConnectionShutdown=0] - client shutdown complete
[12:26:21.690971][strm][0x7f130402d0e0] Indicating QUIC_STREAM_EVENT_SEND_SHUTDOWN_COMPLETE - server send shutdown done
[12:26:21.690975][strm][0x7f130402d0e0] Indicating QUIC_STREAM_EVENT_SHUTDOWN_COMPLETE [ConnectionShutdown=0] - server shutdown complete
Comparison - good sequence without abort:
12:26:20
client 0x7FC0EC003720
server 0x7f130402d0e0
[12:26:20.596074][ api] Enter 21 (0x7fc0ec003720). - client shutdown send
[12:26:20.596113][strm][0x7f130402d0e0] Indicating QUIC_STREAM_EVENT_RECEIVE [0 bytes, 0 buffers, 0x2 flags] - server receive FIN flag
[12:26:20.596120][strm][0x7f130402d0e0] Indicating QUIC_STREAM_EVENT_PEER_SEND_SHUTDOWN - server peer send shutdown
[12:26:20.597703][ api] Enter 22 (0x7f130402d0e0). - server sends trailers
[12:26:20.597792][strm][0x7fc0ec003720] Indicating QUIC_STREAM_EVENT_SEND_SHUTDOWN_COMPLETE - client send shutdown done
[12:26:20.597824][strm][0x7fc0ec003720] Indicating QUIC_STREAM_EVENT_RECEIVE [20 bytes, 1 buffers, 0x0 flags] - client receives trailers
10:26:20.5978784[HandlerMessage] poolId: 1054474, workerId: 39785641, requestId: 0, memberName: ReadFrameEnvelopeAsync, message: Received frame 1 of length 18.
[12:26:20.598337][ api] Enter 21 (0x7f130402d0e0). - server shutdown send
10:26:20.5986209[Info] thisOrContextObject: State#36736776, memberName: HandleEvent, message: [strm][0x7FC0EC003720] Stream received event RECEIVE
[12:26:20.598614][strm][0x7fc0ec003720] Indicating QUIC_STREAM_EVENT_RECEIVE [0 bytes, 0 buffers, 0x2 flags] - client receive FIN flag
10:26:20.5986469[Info] thisOrContextObject: State#36736776, memberName: HandleEventRecv, message: [strm][0x7FC0EC003720] Stream received 0 bytes with FIN flag
10:26:20.5986546[Info] thisOrContextObject: State#36736776, memberName: HandleEvent, message: [strm][0x7FC0EC003720] Stream received event PEER_SEND_SHUTDOWN
10:26:20.5986571[Info] thisOrContextObject: State#36736776, memberName: HandleEventPeerSendShutdown, message: [strm][0x7FC0EC003720] Stream completing resettable event source.
10:26:20.5986610[Info] thisOrContextObject: State#36736776, memberName: HandleEvent, message: [strm][0x7FC0EC003720] Stream received event SHUTDOWN_COMPLETE
10:26:20.5986633[Info] thisOrContextObject: State#36736776, memberName: HandleEventShutdownComplete, message: [strm][0x7FC0EC003720] Stream completing resettable event source.
[12:26:20.598652][strm][0x7fc0ec003720] Indicating QUIC_STREAM_EVENT_PEER_SEND_SHUTDOWN - client peer send shutdown
[12:26:20.598659][strm][0x7fc0ec003720] Indicating QUIC_STREAM_EVENT_SHUTDOWN_COMPLETE [ConnectionShutdown=0] - client shutdown complete
[12:26:20.598747][strm][0x7f130402d0e0] Indicating QUIC_STREAM_EVENT_SEND_SHUTDOWN_COMPLETE - server send shutdown done
[12:26:20.598757][strm][0x7f130402d0e0] Indicating QUIC_STREAM_EVENT_SHUTDOWN_COMPLETE [ConnectionShutdown=0] - server shutdown complete
10:26:20.5993956[Info] thisOrContextObject: State#36736776, memberName: Dispose, message: [strm][0x7FC0EC003720] Stream disposing True state=[strm][0x7FC0EC003720] read=ReadsCompleted, send=Finished, shutdownSend=Finished, shutdown=Finished
10:26:20.5994141[Info] thisOrContextObject: State#36736776, memberName: Dispose, message: [strm][0x7FC0EC003720] Stream disposing(callShutdown=True, abortRead=False, completeRead=False, releaseHandles=True) state=[strm][0x7FC0EC003720] read=ReadsCompleted, send=Finished, shutdownSend=Finished, shutdown=Finished
10:26:20.5994350[Info] thisOrContextObject: State#36736776, memberName: StartShutdown, message: [strm][0x7FC0EC003720] Stream StartShutdown flags=GRACEFUL error=0
10:26:20.5994435[Info] thisOrContextObject: State#36736776, memberName: Cleanup, message: [strm][0x7FC0EC003720] releasing handles.
10:26:20.5994527[Info] thisOrContextObject: State#36736776, memberName: Dispose, message: [strm][0x7FC0EC003720] Stream disposed state=[strm][0x7FC0EC003720] read=ReadsCompleted, send=Finished, shutdownSend=Finished, shutdown=Finished
10:26:20.6043579[Info] thisOrContextObject: (null), memberName: Operations, message: POST Duplex Slow --> StatusCode: 200, ReasonPhrase: 'OK', Version: 3.0, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
Date: Thu, 07 Oct 2021 10:26:20 GMT
Server: Kestrel
}, Trailing Headers:
{
crc32: 363092003
}