Skip to content

[HTTP/3] We don't drain H3 stream after trailing headers #60118

Open
@ManickaP

Description

@ManickaP
Member

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):

// There may be more frames after this one, but they would all be unknown extension
// frames that we are allowed to skip. Just close the stream early.
// Note: if a server sends additional HEADERS or DATA frames at this point, it
// would be a connection error -- not draining the stream means we won't catch this.

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
}

Activity

ghost added
untriagedNew issue has not been triaged by the area owner
on Oct 7, 2021
ghost

ghost commented on Oct 7, 2021

@ghost

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

Issue Details

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):

// There may be more frames after this one, but they would all be unknown extension
// frames that we are allowed to skip. Just close the stream early.
// Note: if a server sends additional HEADERS or DATA frames at this point, it
// would be a connection error -- not draining the stream means we won't catch this.

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
}
Author: ManickaP
Assignees: -
Labels:

area-System.Net.Http, untriaged

Milestone: -
added
untriagedNew issue has not been triaged by the area owner
and removed
untriagedNew issue has not been triaged by the area owner
on Oct 7, 2021
geoffkizer

geoffkizer commented on Oct 11, 2021

@geoffkizer
Contributor

I'm confused by the comment in the code about "extension frames"... are such frames allowed after the trailer section, or not?

scalablecory

scalablecory commented on Oct 11, 2021

@scalablecory
Contributor

I'm confused by the comment in the code about "extension frames"... are such frames allowed after the trailer section, or not?

Yes. Per Section 4.1:

An HTTP message (request or response) consists of:

  1. the header section, sent as a single HEADERS frame (see Section 7.2.2),
  2. optionally, the content, if present, sent as a series of DATA frames (see Section 7.2.1), and
  3. optionally, the trailer section, if present, sent as a single HEADERS frame.

...

Frames of unknown types (Section 9), including reserved frames (Section 7.2.8) MAY be sent on a request or push stream before, after, or interleaved with other frames described in this section.

scalablecory

scalablecory commented on Oct 11, 2021

@scalablecory
Contributor

Note that we decided to ignore anything after trailers (I don't know the exact reason)

Per #60118 (comment), anything after trailers SHOULD be an extension that we don't support and per the standard must ignore.

So fully ignoring the stream is "fine", but means you won't catch protocol errors like invalid frame enveloping or non-extension frames being where they shouldn't be. We'd want to decide where these errors should surface if we do want to check for them.

added and removed
untriagedNew issue has not been triaged by the area owner
on Oct 19, 2021
karelz

karelz commented on Oct 19, 2021

@karelz
Member

Triage:

  • We should not abort when all we need to do is read EOF (no extension frames) -- we mess up log files on server side, which may trigger questions and concerns.
  • If there are extension frames, we expect it will be rare scenario for a while.
added this to the 7.0.0 milestone on Oct 19, 2021
modified the milestones: 7.0.0, Future on Jun 28, 2022
self-assigned this
on Apr 11, 2025
added
in-prThere is an active PR which will close this issue when it is merged
on Jun 4, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

area-System.Net.Httpbugin-prThere is an active PR which will close this issue when it is merged

Type

No type

Projects

No projects

Relationships

None yet

    Development

    Participants

    @scalablecory@karelz@antonfirsov@ManickaP@geoffkizer

    Issue actions

      [HTTP/3] We don't drain H3 stream after trailing headers · Issue #60118 · dotnet/runtime