Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[HTTP/3] Should QuicConnection.Dispose abort? #60235

Closed
JamesNK opened this issue Oct 10, 2021 · 21 comments
Closed

[HTTP/3] Should QuicConnection.Dispose abort? #60235

JamesNK opened this issue Oct 10, 2021 · 21 comments

Comments

@JamesNK
Copy link
Member

JamesNK commented Oct 10, 2021

When QuicConnection.Dispose is called it sends an abort with error code 0. Is QuicConnection sending an abort here the right behavior?

For comparison: When a browser using HTTP/3 is closed, the browser closes the QUIC transport without an abort.

One of the reasons I bring it up is there doesn't appear to be a way to simulate browser behavior using QuicConnection. Connections always close with an abort, not with the transport being closed.

@dotnet-issue-labeler dotnet-issue-labeler bot added the untriaged New issue has not been triaged by the area owner label Oct 10, 2021
@ghost
Copy link

ghost commented Oct 10, 2021

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

Issue Details

When QuicConnection.Dispose is called it sends an abort with error code 0. Is sending an abort here the right behavior?

For comparison: When a browser using HTTP/3 is closed, the browser closes the QUIC transport without an abort.

Author: JamesNK
Assignees: -
Labels:

area-System.Net.Http

Milestone: -

@karelz
Copy link
Member

karelz commented Oct 19, 2021

Triage: We should make it part of QUIC API review. We might stick to current implementation.

@karelz karelz added this to the 7.0.0 milestone Oct 19, 2021
@karelz karelz removed the untriaged New issue has not been triaged by the area owner label Oct 19, 2021
@geoffkizer
Copy link
Contributor

To clarify:

There are essentially two ways to close a QUIC connection:
(1) Idle timeout. Basically the client does nothing and lets the timeout expire, and the connection is closed.
(2) Immediate close. The client sends a CONNECTION_CLOSE frame with an error code to initiate connection closure.

Additionally, the "immediate close" comes in two flavors:
(a) The error code indicates a QUIC protocol error, i.e. protocol violation of some sort. This can also be NO_ERROR (which is 0).
(b) The error code is an application error code; in this case its meaning is entirely application defined.

When you say this:

When QuicConnection.Dispose is called it sends an abort with error code 0.

Do you mean we are sending a CONNECTION_CLOSE with app error code = 0? That seems like incorrect behavior.

Or do you mean we are sending CONNECTION_CLOSE with QUIC error code = 0, i.e. NO_ERROR? That seems reasonable.

For comparison: When a browser using HTTP/3 is closed, the browser closes the QUIC transport without an abort.

Meaning, it lets the connection idle timeout?

It's not clear to me whether it's preferred to send CONNECTION_CLOSE with QUIC error code = NO_ERROR vs just letting the connection idle timeout. The former seems better to me, in that it lets the server know promptly that the connection can be closed, as opposed to waiting for the idle timeout. That said, if the consensus behavior here is just to idle timeout, maybe we should do that.

@ManickaP
Copy link
Member

I tried to reproduce this with H/3 Kestrel server and MsQuicConnection on the client side and the server connection will get closed with QUIC_CONNECTION_EVENT_SHUTDOWN_INITIATED_BY_TRANSPORT circa 15 seconds after client disposed the MsQuicConnection. Which seems exactly like what you're after.

In MsQuicConnection.Dispose we close the connection with silent flag:

MsQuicApi.Api.ConnectionShutdownDelegate(
_state.Handle,
QUIC_CONNECTION_SHUTDOWN_FLAGS.SILENT,
0);

Which doesn't send anything on the wire docs:

The connection is immediately shutdown without informing the peer.

Leading to the peer side connection waiting on the idle timeout and then getting closed "by transport".

But if you're talking about HttpClient and its internal handling of QuicConnection. Then the client does properly closes the QuicConnection under any circumstances:

_connectionClosedTask = _connection.CloseAsync((long)Http3ErrorCode.NoError).AsTask();

It'll always wait for all streams to finish and then it'll gracefully close the connection (informing the peer with application code NoError). And I think this behavior is correct as it is now.

BTW, you can achieve the same thing by killing the client app right after processing the response without disposing the HttpClient, which IMHO corresponds to closing the browser.

Or did I misunderstood your description? Please let me know.

@JamesNK
Copy link
Member Author

JamesNK commented Oct 21, 2021

the server connection will get closed with QUIC_CONNECTION_EVENT_SHUTDOWN_INITIATED_BY_TRANSPORT circa 15 seconds after client disposed the MsQuicConnection

Hmm, I recall my testing with a browser + Kestrel has the server immediately end its connection when the browser is closed. Next time I have a HTTP/3 website setup I'll test again.

@scalablecory
Copy link
Contributor

Pure speculation --

Is it possible for browsers to store TLS parameters and "fast resume" a connection without 0-RTT? This would explain them wanting to time out.

@ManickaP
Copy link
Member

Next time I have a HTTP/3 website setup I'll test again.

@JamesNK Could you collect msquic logs or at least Private.InternalDiagnostics.System.Net.Quic traces, so we can see and compare the events?

@JamesNK
Copy link
Member Author

JamesNK commented Oct 25, 2021

Logs of this happening are already recorded here - #60133 (comment)

@ManickaP
Copy link
Member

Yeah, thanks, but there are no timestamps though so we don't know when the 'shutdown initiated by transport' happened (right after stream dispose or after a certain timeout):

dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event SHUTDOWN_INITIATED_BY_TRANSPORT ->

Unless you can say from the logs somehow.

@JamesNK
Copy link
Member Author

JamesNK commented Oct 26, 2021

Logs with timestamp:

[13:45:07.488] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16802227,HandleEvent,(null) Stream received event START_COMPLETE ->
[13:45:07.488] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16802227,.ctor,[strm][0x2166102F510] Outbound unidirectional stream created in connection [conn][0x21660D75020]. ->
[13:45:07.509] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#258006,NativeCallbackHandler,[conn][0x21660D75020] Connection received event DATAGRAM_STATE_CHANGED ->
[13:45:07.510] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[3]
      Stream id "0HMCO37DOFV64:00000003" type Unidirectional connected.
[13:45:07.531] dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
      WriteAsync[1]
      00                                                 .
[13:45:07.535] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16802227,HandleEvent,[strm][0x2166102F510] Stream received event SEND_COMPLETE ->
[13:45:07.536] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#258006,NativeCallbackHandler,[conn][0x21660D75020] Connection received event DATAGRAM_STATE_CHANGED ->
[13:45:07.544] dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
      WriteAsync[7]
      04 05 06 80 00 80 00                               .......
[13:45:07.545] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16802227,HandleEvent,[strm][0x2166102F510] Stream received event SEND_COMPLETE ->
[13:45:07.551] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#9010854,ReadAsync,[strm][0x21660D762E0] Stream reading into Memory of '4096' bytes. ->
[13:45:07.554] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#9010854,ReadAsync,[strm][0x21660D762E0] Stream reading into Memory of '4096' bytes. ->
[13:45:07.555] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMCO37DOFV64:00000002" type Unidirectional accepted.
[13:45:07.557] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43856670,ReadAsync,[strm][0x21660D765B0] Stream reading into Memory of '4096' bytes. ->
[13:45:07.557] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43856670,HandleEvent,[strm][0x21660D765B0] Stream received event PEER_SEND_SHUTDOWN ->
[13:45:07.557] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43856670,HandleEventPeerSendShutdown,[strm][0x21660D765B0] Stream completing resettable event source. ->
[13:45:07.559] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMCO37DOFV64:00000000" type Bidirectional accepted.
[13:45:07.568] dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
      ReadAsync[52]
      00 04 1D 01 80 01 00 00  06 80 04 00 00 07 40 64   ........ ......@d
      C0 00 00 08 8D BC AE 64  C0 00 00 00 6F D0 0F 17   A....¼rd A...oD..
      C0 00 00 08 A0 53 61 DB  02 FB D5 80 0F 07 00 04   A... SaU .ûO.....
      00 75 3D 30                                        .u=0
[13:45:07.579] trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMCO37DOFV64" received SETTINGS frame for stream ID 2 with length 29.
[13:45:07.587] trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMCO37DOFV64" received 37049557467 frame for stream ID 2 with length 2.
[13:45:07.587] dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
      ReadAsync[439]
      01 41 B4 00 00 D1 50 8F  F1 E3 C2 FD 4A 84 D8 5A   .A'..ÑP. ñaAyJ.OZ
      27 4A 6B 65 72 1E 9F D7  C1 2F 00 41 48 B1 27 5A   'Jker..x A/.AH±'Z
      D1 FF B8 FE 6F 4F 61 E9  35 B4 FF 3F 7D E0 FE 5F   Ñÿ,_oOaé 5'ÿ?}à__
      6B F9 FA 53 F9 C4 73 CD  41 54 BD 3D 87 A4 BF CF   kùúSùÄsI AT½=.¿I
      DF 78 3F 97 DA FE 7E 94  FE 7E F4 9D 2A 42 A5 DB   ßx?.U_~. _~ô.*B¥U
      07 54 9F CF DF 78 3F 97  DF FE 7F 2F 04 41 48 B1   .T.Ißx?. ß_./.AH±
      27 5A D1 AD 49 E3 35 05  02 3F 30 2F 06 41 48 B1   'ZÑ-Ia5. .?0/.AH±
      27 5A D1 AD 5D 03 4C A7  B2 9F 88 FE 79 1A A9 0F   'ZÑ-].L§ ².._y.c.
      E1 1F CF FF 1F 5F 50 D4  D0 7F 66 A2 81 B0 DA E0   á.Iÿ._PO D.f¢.°Uà
      53 FA E4 6A A4 3F 84 29  A7 7A 81 02 E0 FB 53 96   Súäj?.) §z..àûS.
      AE 4E 35 FD A9 0D 75 D0  5E 45 8F 31 92 C3 6C BA   rN5yc.uD ^E.1.Alº
      BB 2E 29 FD 66 C7 BF 46  7F A5 28 37 52 A9 88 A4   ».)yfÇ¿F .¥(7Rc.
      EA 7F ED 4B D3 D8 7A 4A  C3 ED 2E 05 DA 70 0E 2E   ê.íKOOzJ Aí..Up..
      F0 54 DC 39 47 61 98 6D  97 57 65 CF 5F 0E E5 49   dTÜ9Ga.m .WeI_.åI
      7C A5 89 D3 4D 1F 43 AE  BA 0C 41 A4 C7 A9 8F 33   |¥.OM.Cr º.AÇc.3
      A6 9A 3F DF 9A 68 FA 1D  75 D0 62 0D 26 3D 4C 79   ▌.?ß.hú. uDb.&=Ly
      A6 8F BE D0 01 77 FE 8D  48 E6 2B 03 EE 69 7E 8D   ▌._D.w_. Hæ+.îi~.
      48 E6 2B 1E 0B 1D 7F 46  A4 73 15 81 D7 54 DF 5F   Hæ+....F s..xTß_
      2C 7C FD F6 80 0B BD F4  3A EB A0 C4 1A 4C 7A 98   ,|yö..½ô :ë Ä.Lz.
      41 A6 A8 B2 2C 5F 24 9C  75 4C 5F BE F0 46 CF DF   A▌"²,_$. uL__dFIß
      68 00 BB FF 2F 03 41 48  B4 A5 49 27 59 06 49 7F   h.»ÿ/.AH '¥I'Y.I.
      83 A8 F5 17 2F 03 41 48  B4 A5 49 27 5A 93 C8 5F   ."o./.AH '¥I'Z.E_
      86 A8 7D CD 30 D2 5F 2F  03 41 48 B4 A5 49 27 5A   ."}I0O_/ .AH'¥I'Z
      D4 16 CF 02 3F 31 2F 03  41 48 B4 A5 49 27 5A 42   O.I.?1/. AH'¥I'ZB
      A1 3F 86 90 E4 B6 92 D4  9F DF 5F 39 8B 2D 4B 70   ¡?..ä¶.O .ß_9.-Kp
      DD F4 5A BE FB 40 05 DF  55 9D 19 A2 B5 05 B2 0C   YôZ_û@.ß U..¢µ.².
      7A 5E F7 B7 FE 08 02 0A  C0 79 61 03 78 41 70 4F   z^÷·_... Aya.xApO
      DC 65 F5 DE 03 9F BF                               Üeo_..¿
[13:45:07.587] trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMCO37DOFV64" received HEADERS frame for stream ID 0 with length 436.
[13:45:07.587] trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMCO37DOFV64" received 984832 frame for stream ID 2 with length 4.
[13:45:07.630] dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
      ReadAsync[0]
[13:45:07.682] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/3 GET https://www.kestrelhttp3.com/ - -
[13:45:07.690] dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMCO37DOFV64", Request id "0HMCO37DOFV64:00000000": started reading request body.
[13:45:07.692] dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMCO37DOFV64", Request id "0HMCO37DOFV64:00000000": done reading request body.
[13:45:07.720] trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMCO37DOFV64" sending HEADERS frame for stream ID 0 with length 92.
[13:45:07.725] trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMCO37DOFV64" sending DATA frame for stream ID 0 with length 20.
[13:45:07.725] dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
      WriteAsync[117]
      01 40 5C 00 00 D9 34 64  61 74 65 1D 54 75 65 2C   .@\..U4d ate.Tue,
      20 32 36 20 4F 63 74 20  32 30 32 31 20 30 30 3A    26 Oct  2021 00:
      34 35 3A 30 36 20 47 4D  54 36 73 65 72 76 65 72   45:06 GM T6server
      07 4B 65 73 74 72 65 6C  37 00 61 6C 74 2D 73 76   .Kestrel 7.alt-sv
      63 14 68 33 3D 22 3A 35  30 30 31 22 3B 20 6D 61   c.h3=":5 001"; ma
      3D 38 36 34 30 30 34 74  65 73 74 03 66 6F 6F 00   =864004t est.foo.
      14 48 65 6C 6C 6F 20 57  6F 72 6C 64 21 20 48 54   .Hello W orld! HT
      54 50 2F 33 20                                     TP/3
[13:45:07.726] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43856670,HandleEvent,[strm][0x21660D765B0] Stream received event SEND_COMPLETE ->
[13:45:07.733] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/3 GET https://www.kestrelhttp3.com/ - - - 200 - - 55.1409ms
[13:45:07.740] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMCO37DOFV64:00000000" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
[13:45:07.740] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43856670,HandleEvent,[strm][0x21660D765B0] Stream received event SEND_SHUTDOWN_COMPLETE ->
[13:45:07.740] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43856670,HandleEvent,[strm][0x21660D765B0] Stream received event SHUTDOWN_COMPLETE ->
[13:45:07.740] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43856670,HandleEventShutdownComplete,[strm][0x21660D765B0] Stream completing resettable event source. ->
[13:45:07.742] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43856670,Dispose,[strm][0x21660D765B0] Stream disposing True ->
[13:45:07.742] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43856670,Cleanup,[strm][0x21660D765B0] releasing handles. ->
[13:45:07.742] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43856670,Dispose,[strm][0x21660D765B0] Stream disposed ->
[13:45:07.776] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#258006,NativeCallbackHandler,[conn][0x21660D75020] Connection received event PEER_STREAM_STARTED ->
[13:45:07.776] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,.ctor,[strm][0x21660D765B0] Inbound bidirectional stream created in connection [conn][0x21660D75020]. ->
[13:45:07.776] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#9010854,HandleEvent,[strm][0x21660D762E0] Stream received event RECEIVE ->
[13:45:07.776] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#9010854,HandleEventRecv,[strm][0x21660D762E0] Stream received 9 bytes ->
[13:45:07.777] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,HandleEvent,[strm][0x21660D765B0] Stream received event RECEIVE ->
[13:45:07.777] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,HandleEventRecv,[strm][0x21660D765B0] Stream received 405 bytes with FIN flag ->
[13:45:07.777] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#9010854,ReadAsync,[strm][0x21660D762E0] Stream reading into Memory of '4096' bytes. ->
[13:45:07.777] dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
      ReadAsync[9]
      80 0F 07 00 04 04 75 3D  31                        ......u= 1
[13:45:07.778] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,ReadAsync,[strm][0x21660D765B0] Stream reading into Memory of '4096' bytes. ->
[13:45:07.778] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMCO37DOFV64:00000004" type Bidirectional accepted.
[13:45:07.778] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,HandleEvent,[strm][0x21660D765B0] Stream received event PEER_SEND_SHUTDOWN ->
[13:45:07.778] trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMCO37DOFV64" received 984832 frame for stream ID 2 with length 4.
[13:45:07.778] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,HandleEventPeerSendShutdown,[strm][0x21660D765B0] Stream completing resettable event source. ->
[13:45:07.778] dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
      ReadAsync[405]
      01 41 92 00 00 D1 50 8F  F1 E3 C2 FD 4A 84 D8 5A   .A...ÑP. ñaAyJ.OZ
      27 4A 6B 65 72 1E 9F D7  51 89 62 51 F7 31 0F 52   'Jker..x Q.bQ÷1.R
      E6 21 FF 2F 00 41 48 B1  27 5A D1 FF B8 FE 6F 4F   æ!ÿ/.AH± 'ZÑÿ,_oO
      61 E9 35 B4 FF 3F 7D E0  FE 5F 6B F9 FA 53 F9 C4   aé5'ÿ?}à __kùúSùÄ
      73 CD 41 54 BD 3D 87 A4  BF CF DF 78 3F 97 DA FE   sIAT½=. ¿Ißx?.U_
      7E 94 FE 7E F4 9D 2A 42  A5 DB 07 54 9F CF DF 78   ~._~ô.*B ¥U.T.Ißx
      3F 97 DF FE 7F 2F 04 41  48 B1 27 5A D1 AD 49 E3   ?.ß_./.A H±'ZÑ-Ia
      35 05 02 3F 30 5F 50 D4  D0 7F 66 A2 81 B0 DA E0   5..?0_PO D.f¢.°Uà
      53 FA E4 6A A4 3F 84 29  A7 7A 81 02 E0 FB 53 96   Súäj?.) §z..àûS.
      AE 4E 35 FD A9 0D 75 D0  5E 45 8F 31 92 C3 6C BA   rN5yc.uD ^E.1.Alº
      BB 2E 29 FD 66 C7 BF 46  7F A5 28 37 52 A9 88 A4   ».)yfÇ¿F .¥(7Rc.
      EA 7F ED 4B D3 D8 7A 4A  C3 ED 2E 05 DA 70 0E 2E   ê.íKOOzJ Aí..Up..
      F0 54 DC 39 47 61 98 6D  97 57 65 CF 2F 06 41 48   dTÜ9Ga.m .WeI/.AH
      B1 27 5A D1 AD 5D 03 4C  A7 B2 9F 88 FE 79 1A A9   ±'ZÑ-].L §².._y.c
      0F E1 1F CF 5F 0E B1 35  23 98 AC 0F B9 A5 FA 35   .á.I_.±5 #.¬.1¥ú5
      23 98 AC 78 2C 75 FD 1A  91 CC 56 07 5D 53 7D 1A   #.¬x,uy. .IV.]S}.
      91 CC 56 11 DE 6F F7 E6  9A 3E 8D 48 E6 2B 1F 3F   .IV._o÷æ .>.Hæ+.?
      5F 2C 7C FD F6 80 0B BD  2F 03 41 48 B4 A5 49 27   _,|yö..½ /.AH'¥I'
      59 06 49 7F 88 40 E9 2A  C7 B0 D3 1A AF 2F 03 41   Y.I..@é* Ç°O._/.A
      48 B4 A5 49 27 5A 93 C8  5F 85 A8 EB 10 F6 23 2F   H'¥I'Z.E _."ë.ö#/
      03 41 48 B4 A5 49 27 5A  42 A1 3F 84 35 23 98 BF   .AH'¥I'Z B¡?.5#.¿
      5D 95 9D 29 AD 17 18 63  C7 8F 0B F5 2A 13 61 68   ]..)-..c Ç..o*.ah
      9D 29 AD 95 C8 7A 58 DF  5F 39 8B 2D 4B 70 DD F4   .)-.EzXß _9.-KpYô
      5A BE FB 40 05 DF 55 9D  19 A2 B5 05 B2 0C 7A 5E   Z_û@.ßU. .¢µ.².z^
      F7 B7 FE 08 02 0A C0 79  61 03 78 41 70 4F DC 65   ÷·_...Ay a.xApOÜe
      F5 DE 03 9F BF                                     o_..¿
[13:45:07.778] trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMCO37DOFV64" received HEADERS frame for stream ID 4 with length 402.
[13:45:07.779] dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
      ReadAsync[0]
[13:45:07.779] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/3 GET https://www.kestrelhttp3.com/favicon.ico - -
[13:45:07.779] dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMCO37DOFV64", Request id "0HMCO37DOFV64:00000004": started reading request body.
[13:45:07.779] dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMCO37DOFV64", Request id "0HMCO37DOFV64:00000004": done reading request body.
[13:45:07.779] trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMCO37DOFV64" sending HEADERS frame for stream ID 4 with length 92.
[13:45:07.779] trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMCO37DOFV64" sending DATA frame for stream ID 4 with length 20.
[13:45:07.779] dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
      WriteAsync[117]
      01 40 5C 00 00 D9 34 64  61 74 65 1D 54 75 65 2C   .@\..U4d ate.Tue,
      20 32 36 20 4F 63 74 20  32 30 32 31 20 30 30 3A    26 Oct  2021 00:
      34 35 3A 30 37 20 47 4D  54 36 73 65 72 76 65 72   45:07 GM T6server
      07 4B 65 73 74 72 65 6C  37 00 61 6C 74 2D 73 76   .Kestrel 7.alt-sv
      63 14 68 33 3D 22 3A 35  30 30 31 22 3B 20 6D 61   c.h3=":5 001"; ma
      3D 38 36 34 30 30 34 74  65 73 74 03 66 6F 6F 00   =864004t est.foo.
      14 48 65 6C 6C 6F 20 57  6F 72 6C 64 21 20 48 54   .Hello W orld! HT
      54 50 2F 33 20                                     TP/3
[13:45:07.779] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/3 GET https://www.kestrelhttp3.com/favicon.ico - - - 200 - - 0.4209ms
[13:45:07.779] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,HandleEvent,[strm][0x21660D765B0] Stream received event SEND_COMPLETE ->
[13:45:07.779] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMCO37DOFV64:00000004" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
[13:45:07.780] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,HandleEvent,[strm][0x21660D765B0] Stream received event SEND_SHUTDOWN_COMPLETE ->
[13:45:07.781] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,HandleEvent,[strm][0x21660D765B0] Stream received event SHUTDOWN_COMPLETE ->
[13:45:07.781] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,HandleEventShutdownComplete,[strm][0x21660D765B0] Stream completing resettable event source. ->
[13:45:07.781] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,Dispose,[strm][0x21660D765B0] Stream disposing True ->
[13:45:07.781] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,Cleanup,[strm][0x21660D765B0] releasing handles. ->
[13:45:07.781] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18202863,Dispose,[strm][0x21660D765B0] Stream disposed ->
[13:45:13.266] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#258006,NativeCallbackHandler,[conn][0x21660D75020] Connection received event SHUTDOWN_INITIATED_BY_TRANSPORT ->
[13:45:13.267] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#9010854,HandleEvent,[strm][0x21660D762E0] Stream received event SHUTDOWN_COMPLETE ->
[13:45:13.267] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#9010854,HandleEventConnectionClose,[strm][0x21660D762E0] Stream handling connection [conn][0x21660D75020] close with code 0 ->
[13:45:13.290] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16802227,HandleEvent,[strm][0x2166102F510] Stream received event SEND_SHUTDOWN_COMPLETE ->
[13:45:13.290] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16802227,HandleEvent,[strm][0x2166102F510] Stream received event SHUTDOWN_COMPLETE ->
[13:45:13.290] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16802227,HandleEventConnectionClose,[strm][0x2166102F510] Stream handling connection [conn][0x21660D75020] close with code 0 ->
[13:45:13.291] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#258006,NativeCallbackHandler,[conn][0x21660D75020] Connection received event SHUTDOWN_COMPLETE ->
[13:45:13.291] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[11]
      Stream id "0HMCO37DOFV64:00000002" read aborted by peer with error code 0.
[13:45:13.292] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[12]
      Stream id "0HMCO37DOFV64:00000003" write aborted by peer with error code 0.
[13:45:13.292] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMCO37DOFV64:00000003" shutting down writes because: "Connection aborted by peer (0).".
[13:45:13.273] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[5]
      Connection id "0HMCO37DOFV64" aborted by peer with error code 0.
      System.Net.Quic.QuicConnectionAbortedException: Connection aborted by peer (0).
         at System.Net.Quic.Implementations.MsQuic.MsQuicConnection.AcceptStreamAsync(CancellationToken cancellationToken)
         at System.Net.Quic.QuicConnection.AcceptStreamAsync(CancellationToken cancellationToken)
         at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicConnectionContext.AcceptAsync(CancellationToken cancellationToken) in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicConnectionContext.cs:line 97
[13:45:13.306] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[6]
      Connection id "0HMCO37DOFV64" aborted by application with error code 0 because: "The client closed the connection.".
[13:45:13.311] dbug: Microsoft.AspNetCore.Server.Kestrel.Http3[44]
      Connection id "0HMCO37DOFV64" is closed. The last processed stream ID was 4.
[13:45:13.312] dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[2]
      Connection id "0HMCO37DOFV64" stopped.
[13:45:13.313] dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#258006,Dispose,[conn][0x21660D75020] Connection disposing True ->

Screen capture that was used to create these logs. As you can see, the server immediately receives SHUTDOWN_INITIATED_BY_TRANSPORT when the browser is closed.

http3closebrowser

@ManickaP
Copy link
Member

I see, I don't think this is possible with msquic at the moment. ConnectionShutdown seems to be only for application initiated connection close, i.e.: frame type 0x1D https://www.rfc-editor.org/rfc/rfc9000.html#name-connection_close-frames. Unless I've missed something. Can you confirm @nibanks?

@nibanks
Copy link

nibanks commented Oct 26, 2021

@ManickaP / @JamesNK can you please clarify the ask here? Are you trying to kill a connection without sending the connection close frame?

@ManickaP
Copy link
Member

AFAIU, @JamesNK would like to simulate behavior of a closed browser window with System.Net.Quic, which is sending CONNECTION_CLOSE frame of "transport" layer (0x1C, and getting SHUTDOWN_INITIATED_BY_TRANSPORT immediately on the peer).

This can be achieved by dropping the connection and waiting IDLE_TIMEOUT on the peer, but it's not immediate.

@nibanks
Copy link

nibanks commented Oct 26, 2021

By design, the MsQuic API only exposes the ability for an app to send application close frames, not transport connection close ones. If you want to trigger a faster idle timeout, just set a shorter idle timeout period for that particular test.

@ManickaP
Copy link
Member

Thanks for the explanation Nick.

@JamesNK in the light of all this info I'll close this.
You can achieve the same thing with IDLE_TIMEOUT and disposing QuicConnection without calling CloseAsync, it's just not immediate as with the browser. There's no option in msquic to achieve immediate transport close by design.

@geoffkizer
Copy link
Contributor

By design, the MsQuic API only exposes the ability for an app to send application close frames, not transport connection close ones.

What's the reason for this?

Given that browsers do send a transport connection close, I suspect we will get customer questions about this.

@nibanks
Copy link

nibanks commented Oct 26, 2021

What's the reason for this?

Per protocol, apps send application close frames. Only the QUIC transport itself sends connection close frames.

@geoffkizer
Copy link
Contributor

So basically, the browsers are doing the wrong thing?

@nibanks
Copy link

nibanks commented Oct 26, 2021

I still don't quite understand the problem here. Can someone elaborate more please?

which is sending CONNECTION_CLOSE frame of "transport" layer (0x1C, and getting SHUTDOWN_INITIATED_BY_TRANSPORT immediately on the peer)

What error is being sent in this case?

@geoffkizer
Copy link
Contributor

Actually, I'm not sure I understand either.

I would expect that a browser (or any other client app) that wants to close an HTTP3 connection would send app-level (0x1d) CONNECTION_CLOSE with error code = H3_NO_ERROR.

@JamesNK @ManickaP Is that what we actually see with browsers in practice? It's unclear to me from the trace above.

And similarly, I would expect that our HTTP3 logic in SocketsHttpHandler would do the same when it wants to close a connection. Note, though, that users of SocketsHttpHandler cannot directly close a specific connection; rather, a connection will be closed when either (a) the connection pool decides it's no longer needed/wanted; or (b) the user explicitly Disposes the SocketsHttpHandler.

Also note that SocketsHttpHandler should close the QUIC connection by calling QuicConnection.CloseAsync() explicitly, so that it can specify the proper app-level error code for CONNECTION_CLOSE.

There's a separate issue of what QuicConnection.Dispose should do if the user does not call QuicConnection.CloseAsync() first, but it's not relevant to the HTTP3 behavior since our HTTP3 code should always call CloseAsync first. QUIC idle timeout seems fine here to me.

@ManickaP
Copy link
Member

According to logs above, browser sends 0x1C when closed, i.e.: SHUTDOWN_INITIATED_BY_TRANSPORT.
I cannot test with browser (certs and all that jazz) so I cannot confirm this is same with Firefox as well (I assume all chromium based browsers behave the same).
HttpClient will send 0x1D, because that's what msquic exposes and that's what makes sense IMHO.

Comparing with TCP, closed browser tab (in Firefox) will send graceful FIN to end the connection.

Finally, HttpClient is not just used as a browser, it's used in many different ways (proxy, gRPC, REST APIs, ...) so mimicking browser behavior to a T in all cases might not be desirable.

@ghost ghost locked as resolved and limited conversation to collaborators Nov 25, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

6 participants