I noticed in logs that Kestrel logs a BadRequest event after a request is finished. From gRPC benchmarks.
C:\Development\Source\grpc-dotnet [master ≡ +0 ~4 -0 !]> dotnet run -c Release -p .\perf\benchmarkapps\GrpcAspNetCoreServer\ --protocol h3 --logLevel Trace
Warning NETSDK1174: The abbreviation of -p for --project is deprecated. Please use --project.
ASP.NET Core gRPC Benchmarks
----------------------------
Args: --protocol h3 --logLevel Trace
Current directory: C:\Development\Source\grpc-dotnet\perf\benchmarkapps\GrpcAspNetCoreServer
WebHostBuilder loading from: C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App\7.0.0-preview.6.22312.2\Microsoft.AspNetCore.Hosting.dll
Console Logging enabled with level 'Trace'
39.6152 dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
Hosting starting
Address: 127.0.0.1:5000, Protocol: h3
Certificate authentication: False
39.6552 dbug: HttpEventSourceListener[0]
Starting HttpEventSourceListener.
39.6606 trce: Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder[2]
Discovering gRPC methods for BenchmarkServiceImpl.
39.6735 trce: Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder[1]
Added gRPC method 'UnaryCall' to service 'grpc.testing.BenchmarkService'. Method type: Unary, HTTP method: POST, route pattern: '/grpc.testing.BenchmarkService/UnaryCall'.
39.6739 trce: Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder[1]
Added gRPC method 'StreamingCall' to service 'grpc.testing.BenchmarkService'. Method type: DuplexStreaming, HTTP method: POST, route pattern: '/grpc.testing.BenchmarkService/StreamingCall'.
39.6740 trce: Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder[1]
Added gRPC method 'StreamingFromClient' to service 'grpc.testing.BenchmarkService'. Method type: ClientStreaming, HTTP method: POST, route pattern: '/grpc.testing.BenchmarkService/StreamingFromClient'.
39.6740 trce: Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder[1]
Added gRPC method 'StreamingFromServer' to service 'grpc.testing.BenchmarkService'. Method type: ServerStreaming, HTTP method: POST, route pattern: '/grpc.testing.BenchmarkService/StreamingFromServer'.
39.6740 trce: Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder[1]
Added gRPC method 'StreamingBothWays' to service 'grpc.testing.BenchmarkService'. Method type: DuplexStreaming, HTTP method: POST, route pattern: '/grpc.testing.BenchmarkService/StreamingBothWays'.
39.6956 dbug: Microsoft.AspNetCore.Mvc.ModelBinding.ModelBinderFactory[12]
Registered model binder providers, in the following order: Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BinderTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ServicesModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.HeaderModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FloatingPointTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.EnumTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.DateTimeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.TryParseModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CancellationTokenModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ByteArrayModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormFileModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormCollectionModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.KeyValuePairModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.DictionaryModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ArrayModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CollectionModelBinderProvider, Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ComplexObjectModelBinderProvider
39.7173 warn: Microsoft.AspNetCore.Server.Kestrel[0]
Overriding address(es) 'https://localhost:54055, http://localhost:54064'. Binding to endpoints defined via IConfiguration and/or UseKestrel() instead.
39.7420 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeMsQuicConfigurationHandle#51812368,.ctor,MsQuicSafeHandle created ->
39.7468 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeMsQuicListenerHandle#63658128,.ctor,MsQuicSafeHandle created ->
39.7469 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36052245,.ctor,[list][0x2AD75CA8D40] Listener created ->
39.7499 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36052245,.ctor,[list][0x2AD75CA8D40] Listener started ->
39.7511 info: Microsoft.Hosting.Lifetime[14]
Now listening on: https://[::]:5000
39.7512 dbug: Microsoft.AspNetCore.Hosting.Diagnostics[13]
Loaded hosting startup assembly GrpcAspNetCoreServer
Application started.
39.7515 info: Microsoft.Hosting.Lifetime[0]
Application started. Press Ctrl+C to shut down.
39.7515 info: Microsoft.Hosting.Lifetime[0]
Hosting environment: Development
39.7515 info: Microsoft.Hosting.Lifetime[0]
Content root path: C:\Development\Source\grpc-dotnet\perf\benchmarkapps\GrpcAspNetCoreServer
39.7515 dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
Hosting started
45.5521 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeMsQuicConnectionHandle#56251872,.ctor,MsQuicSafeHandle created ->
45.5529 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4878312,.ctor,[conn][0x2EE0F0F5860] Inbound connection created ->
45.5537 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4878312,NativeCallback,[conn][0x2EE0F0F5860] Connection received event IDEAL_PROCESSOR_CHANGED ->
45.5796 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4878312,NativeCallback,[conn][0x2EE0F0F5860] Connection received event CONNECTED ->
45.5828 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[1]
Connection id "0HMIHPF2JUKMI" accepted.
45.5837 dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[39]
Connection id "0HMIHPF2JUKMI" accepted.
45.5842 dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[1]
Connection id "0HMIHPF2JUKMI" started.
45.5850 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4878312,NativeCallback,[conn][0x2EE0F0F5860] Connection received event PEER_STREAM_STARTED ->
45.5854 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeMsQuicStreamHandle#61325552,.ctor,MsQuicSafeHandle created ->
45.5858 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29028787,.ctor,[strm][0x2EE0F17B220] Inbound unidirectional stream created in connection [conn][0x2EE0F0F5860] with StreamId 2. ->
45.5859 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29028787,NativeCallback,[strm][0x2EE0F17B220] Stream received event RECEIVE ->
45.5863 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29028787,HandleEventReceive,[strm][0x2EE0F17B220] Stream received 8 bytes ->
45.5896 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeMsQuicStreamHandle#64923656,.ctor,MsQuicSafeHandle created ->
45.5897 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44624228,.ctor,[strm][0x2EE0F18D070] Outbound unidirectional stream created in connection [conn][0x2EE0F0F5860]. ->
45.5906 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44624228,NativeCallback,[strm][0x2EE0F18D070] Stream received event START_COMPLETE ->
45.5909 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44624228,HandleEventStartComplete,[strm][0x2EE0F18D070] StreamId = 3 ->
45.5967 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4878312,NativeCallback,[conn][0x2EE0F0F5860] Connection received event PEER_STREAM_STARTED ->
45.5967 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeMsQuicStreamHandle#62130720,.ctor,MsQuicSafeHandle created ->
45.5967 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,.ctor,[strm][0x2EE0F18D380] Inbound bidirectional stream created in connection [conn][0x2EE0F0F5860] with StreamId 0. ->
45.5968 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,NativeCallback,[strm][0x2EE0F18D380] Stream received event RECEIVE ->
45.5968 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,HandleEventReceive,[strm][0x2EE0F18D380] Stream received 332 bytes ->
45.5992 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[3]
Stream id "0HMIHPF2JUKMI:00000003" type Unidirectional connected.
45.6037 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44624228,NativeCallback,[strm][0x2EE0F18D070] Stream received event SEND_COMPLETE ->
45.6060 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44624228,NativeCallback,[strm][0x2EE0F18D070] Stream received event SEND_COMPLETE ->
45.6072 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29028787,ReadAsync,[strm][0x2EE0F17B220] Stream reading into Memory of '4096' bytes. ->
45.6078 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29028787,ReadAsync,[strm][0x2EE0F17B220] Stream reading into Memory of '4096' bytes. ->
45.6093 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
Stream id "0HMIHPF2JUKMI:00000002" type Unidirectional accepted.
45.6095 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,ReadAsync,[strm][0x2EE0F18D380] Stream reading into Memory of '4096' bytes. ->
45.6095 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,ReadAsync,[strm][0x2EE0F18D380] Stream reading into Memory of '4096' bytes. ->
45.6095 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,NativeCallback,[strm][0x2EE0F18D380] Stream received event PEER_SEND_SHUTDOWN ->
45.6096 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,HandleEventPeerSendShutdown,[strm][0x2EE0F18D380] Stream completing resettable event source. ->
45.6096 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
Stream id "0HMIHPF2JUKMI:00000000" type Bidirectional accepted.
45.6136 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
Connection id "0HMIHPF2JUKMI" received HEADERS frame for stream ID 0 with length 320.
45.6136 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
Connection id "0HMIHPF2JUKMI" received SETTINGS frame for stream ID 2 with length 5.
45.6240 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
Connection id "0HMIHPF2JUKMI" received DATA frame for stream ID 0 with length 7.
45.6302 info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/3 POST https://localhost:5000/grpc.testing.BenchmarkService/UnaryCall application/grpc -
45.6316 dbug: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[0]
Wildcard detected, all requests with hosts will be allowed.
45.6319 trce: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[2]
All hosts are allowed.
45.6486 dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]
1 candidate(s) found for the request path '/grpc.testing.BenchmarkService/UnaryCall'
45.6491 dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]
Request matched endpoint 'gRPC - /grpc.testing.BenchmarkService/UnaryCall'
45.6496 info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Executing endpoint 'gRPC - /grpc.testing.BenchmarkService/UnaryCall'
45.6562 dbug: Grpc.AspNetCore.Server.ServerCallHandler[10]
Reading message.
45.6579 dbug: Microsoft.AspNetCore.Server.Kestrel[25]
Connection id "0HMIHPF2JUKMI", Request id "0HMIHPF2JUKMI:00000000": started reading request body.
45.6582 dbug: Microsoft.AspNetCore.Server.Kestrel[26]
Connection id "0HMIHPF2JUKMI", Request id "0HMIHPF2JUKMI:00000000": done reading request body.
45.6598 trce: Grpc.AspNetCore.Server.ServerCallHandler[12]
Deserializing 2 byte message to 'Grpc.Testing.SimpleRequest'.
45.6632 trce: Grpc.AspNetCore.Server.ServerCallHandler[13]
Received message.
45.6660 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
Connection id "0HMIHPF2JUKMI" sending HEADERS frame for stream ID 0 with length 76.
45.6660 dbug: Grpc.AspNetCore.Server.ServerCallHandler[15]
Sending message.
45.6703 trce: Grpc.AspNetCore.Server.ServerCallHandler[18]
Serialized 'Grpc.Testing.SimpleResponse' to 2 byte message.
45.6706 trce: Grpc.AspNetCore.Server.ServerCallHandler[16]
Message sent.
45.6718 info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Executed endpoint 'gRPC - /grpc.testing.BenchmarkService/UnaryCall'
45.6720 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
Connection id "0HMIHPF2JUKMI" sending DATA frame for stream ID 0 with length 7.
45.6721 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
Connection id "0HMIHPF2JUKMI" sending HEADERS frame for stream ID 0 with length 17.
45.6721 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,NativeCallback,[strm][0x2EE0F18D380] Stream received event SEND_COMPLETE ->
45.6722 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,NativeCallback,[strm][0x2EE0F18D380] Stream received event SEND_COMPLETE ->
45.6727 info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished HTTP/3 POST https://localhost:5000/grpc.testing.BenchmarkService/UnaryCall application/grpc - - 200 - application/grpc 43.3167ms
45.6732 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
Stream id "0HMIHPF2JUKMI:00000000" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
51.8237 dbug: Microsoft.AspNetCore.Server.Kestrel.BadRequests[28]
Connection id "0HMIHPF2JUKMI", Request id "0HMIHPF2JUKMI:00000000": the connection was closed because the response was not read by the client at the specified minimum data rate.
51.8263 dbug: Microsoft.AspNetCore.Server.Kestrel.Http3[53]
Connection id "0HMIHPF2JUKMI": GOAWAY stream ID 4.
51.8267 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
Connection id "0HMIHPF2JUKMI" sending GOAWAY frame for stream ID 3 with length 1.
51.8268 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44624228,NativeCallback,[strm][0x2EE0F18D070] Stream received event SEND_COMPLETE ->
51.8292 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[6]
Connection id "0HMIHPF2JUKMI" aborted by application with error code 258 because: "The connection was timed out by the server because the response was not read by the client at the specified minimum data rate.".
51.8297 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,NativeCallback,[strm][0x2EE0F18D380] Stream received event SEND_SHUTDOWN_COMPLETE ->
51.8300 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,NativeCallback,[strm][0x2EE0F18D380] Stream received event SHUTDOWN_COMPLETE ->
51.8302 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,HandleEventConnectionClose,[strm][0x2EE0F18D380] Stream handling connection [conn][0x2EE0F0F5860] close ->
51.8367 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29028787,NativeCallback,[strm][0x2EE0F17B220] Stream received event SHUTDOWN_COMPLETE ->
51.8367 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29028787,HandleEventConnectionClose,[strm][0x2EE0F17B220] Stream handling connection [conn][0x2EE0F0F5860] close ->
51.8369 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44624228,NativeCallback,[strm][0x2EE0F18D070] Stream received event SEND_SHUTDOWN_COMPLETE ->
51.8369 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44624228,NativeCallback,[strm][0x2EE0F18D070] Stream received event SHUTDOWN_COMPLETE ->
51.8369 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44624228,HandleEventConnectionClose,[strm][0x2EE0F18D070] Stream handling connection [conn][0x2EE0F0F5860] close ->
51.8371 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
Stream id "0HMIHPF2JUKMI:00000003" shutting down writes because: "Operation aborted.".
51.8378 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,Dispose,[strm][0x2EE0F18D380] Stream disposing True ->
51.8378 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,Cleanup,[strm][0x2EE0F18D380] releasing handles. ->
51.8378 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeMsQuicStreamHandle#62130720,ReleaseHandle,MsQuicSafeHandle released ->
51.8378 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4593845,Dispose,[strm][0x2EE0F18D380] Stream disposed ->
52.0852 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4878312,NativeCallback,[conn][0x2EE0F0F5860] Connection received event SHUTDOWN_COMPLETE ->
52.0871 dbug: Microsoft.AspNetCore.Server.Kestrel.BadRequests[20]
Connection id "0HMIHPF2JUKMI" request processing ended abnormally.
Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was timed out by the server because the response was not read by the client at the specified minimum data rate.
at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicConnectionContext.AcceptAsync(CancellationToken cancellationToken)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3.Http3Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
52.0892 dbug: Microsoft.AspNetCore.Server.Kestrel.Http3[44]
Connection id "0HMIHPF2JUKMI" is closed. The last processed stream ID was 0.
52.0901 dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[2]
Connection id "0HMIHPF2JUKMI" stopped.
52.0902 dbug: HttpEventSourceListener[0]
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#4878312,Dispose,[conn][0x2EE0F0F5860] Connection disposing True ->
Is there an existing issue for this?
Describe the bug
I noticed in logs that Kestrel logs a BadRequest event after a request is finished. From gRPC benchmarks.
Interesting bit:
Expected Behavior
No exception when request completes gracefully
Steps To Reproduce
No response
Exceptions (if any)
No response
.NET Version
No response
Anything else?
No response