Quarantine GET_GracefulServerShutdown_AbortRequestsAfterHostTimeout

[Tratcher]

Failing Test(s)

• Interop.FunctionalTests.Http3.Http3RequestTests.GET_GracefulServerShutdown_AbortRequestsAfterHostTimeout(protocol: Http2)

Error Message

Xunit.Sdk.EqualException: Assert.Equal() Failure
              ↓ (pos 4)
Expected: The connection was aborted because the server···
Actual:   The HTTP/2 connection faulted.
              ↑ (pos 4)

Stacktrace

   at Xunit.Assert.Equal(String expected, String actual, Boolean ignoreCase, Boolean ignoreLineEndingDifferences, Boolean ignoreWhiteSpaceDifferences) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\StringAsserts.cs:line 244
   at Interop.FunctionalTests.Http3.Http3RequestTests.GET_GracefulServerShutdown_AbortRequestsAfterHostTimeout(HttpProtocols protocol) in /_/src/Servers/Kestrel/test/Interop.FunctionalTests/Http3/Http3RequestTests.cs:line 1545
   at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_1.<<InvokeTestMethodAsync>b__1>d.MoveNext() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\Runners\TestInvoker.cs:line 273
--- End of stack trace from previous location ---
   at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\ExecutionTimer.cs:line 54
   at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 96

Logs

[0.001s] [TestLifetime] [Information] Starting test GET_GracefulServerShutdown_AbortRequestsAfterHostTimeout-Http2 at 2022-02-03T23:42:31
[0.014s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting starting
[0.017s] [Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer] [Debug] Using development certificate: CN=localhost (Thumbprint: 1D112901E921649019083FEB4A6328C37B487A26)
[0.018s] [Microsoft.Hosting.Lifetime] [Information] Now listening on: https://127.0.0.1:60384
[0.018s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Debug] Loaded hosting startup assembly Interop.FunctionalTests
[0.018s] [Microsoft.Hosting.Lifetime] [Information] Application started. Press Ctrl+C to shut down.
[0.018s] [Microsoft.Hosting.Lifetime] [Information] Hosting environment: Production
[0.018s] [Microsoft.Hosting.Lifetime] [Information] Content root path: C:\h\w\A9AE0926\w\A976092A\e\
[0.018s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting started
[0.020s] [Microsoft.AspNetCore.Server.Kestrel.Connections] [Debug] Connection id "0HMF7DR9L1H02" accepted.
[0.020s] [Microsoft.AspNetCore.Server.Kestrel.Connections] [Debug] Connection id "0HMF7DR9L1H02" started.
[0.024s] [Microsoft.AspNetCore.Server.Kestrel.Https.Internal.HttpsConnectionMiddleware] [Debug] Connection 0HMF7DR9L1H02 established using the following protocol: Tls13
[0.024s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" sending SETTINGS frame for stream ID 0 with length 18 and flags NONE.
[0.024s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" sending WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
[0.024s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" received SETTINGS frame for stream ID 0 with length 12 and flags NONE.
[0.024s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK.
[0.025s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" received WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
[0.025s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" received HEADERS frame for stream ID 1 with length 20 and flags END_HEADERS.
[0.025s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" received SETTINGS frame for stream ID 0 with length 0 and flags ACK.
[0.025s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request starting HTTP/2 POST https://127.0.0.1:60384/ - -
[0.027s] [Interop.FunctionalTests.Http3.Http3RequestTests] [Information] Server sending response headers
[0.027s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" sending HEADERS frame for stream ID 1 with length 41 and flags END_HEADERS.
[0.027s] [Interop.FunctionalTests.Http3.Http3RequestTests] [Information] Server reading
[0.030s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HMF7DR9L1H02", Request id "0HMF7DR9L1H02:00000001": started reading request body.
[0.031s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" received PING frame for stream ID 0 with length 8 and flags NONE.
[0.032s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" sending PING frame for stream ID 0 with length 8 and flags ACK.
[0.034s] [Interop.FunctionalTests.Http3.Http3RequestTests] [Information] Stopping host
[0.034s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting stopping
[0.034s] [Microsoft.Hosting.Lifetime] [Information] Application is shutting down...
[0.034s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Debug] Connection id "0HMF7DR9L1H02" is closing.
[0.034s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" sending GOAWAY frame for stream ID 0 with length 8 and flags 0x0.
[0.034s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" received DATA frame for stream ID 1 with length 11 and flags NONE.
[1.049s] [Microsoft.AspNetCore.Server.Kestrel.Connections] [Debug] Some connections failed to close gracefully during server shutdown.
[6.098s] [Microsoft.AspNetCore.Server.Kestrel.BadRequests] [Debug] Connection id "0HMF7DR9L1H02", Request id "null": the request timed out because it was not sent by the client at a minimum of 240 bytes/second.
[7.336s] [Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets] [Debug] Connection id "0HMF7DR9L1H02" sending FIN because: "The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout."
[7.337s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Debug] Connection id "0HMF7DR9L1H02" is closed. The last processed stream ID was 1.
[7.337s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "0HMF7DR9L1H02" sending GOAWAY frame for stream ID 0 with length 8 and flags 0x0.
[7.347s] [Microsoft.AspNetCore.Server.Kestrel] [Error] Connection id "0HMF7DR9L1H02", Request id "0HMF7DR9L1H02:00000001": An unhandled exception was thrown by the application.
System.IO.IOException: The request stream was aborted.
 ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/2 connection faulted.
   --- End of inner exception stack trace ---
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2MessageBody.ReadAsync(CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/Http2/Http2MessageBody.cs:line 98
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.ReadAsyncInternal(Memory`1 destination, CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/Http/HttpRequestStream.cs:line 116
   at System.IO.StreamExtensions.ReadUntilEndAsync(Stream stream, Int32 bufferLength, CancellationToken cancellationToken) in /_/src/Servers/Kestrel/shared/test/StreamExtensions.cs:line 84
   at Interop.FunctionalTests.Http3.Http3RequestTests.<>c__DisplayClass27_0.<<GET_GracefulServerShutdown_AbortRequestsAfterHostTimeout>b__0>d.MoveNext() in /_/src/Servers/Kestrel/test/Interop.FunctionalTests/Http3/Http3RequestTests.cs:line 1494
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application) in /_/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs:line 664
[7.347s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request finished HTTP/2 POST https://127.0.0.1:60384/ - - - 200 - - 7321.9003ms
[7.347s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HMF7DR9L1H02", Request id "0HMF7DR9L1H02:00000001": done reading request body.
[7.347s] [Microsoft.AspNetCore.Server.Kestrel] [Information] Connection id "0HMF7DR9L1H02", Request id "0HMF7DR9L1H02:00000001": the application completed without reading the entire request body.
[7.349s] [Microsoft.AspNetCore.Server.Kestrel.Connections] [Debug] Connection id "0HMF7DR9L1H02" stopped.
[7.349s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting stopped
[7.351s] [Microsoft.AspNetCore.Server.Kestrel] [Warning] As of "02/03/2022 23:42:38 +00:00", the heartbeat has been running for "00:00:01.2496930" which is longer than "00:00:01". This could be caused by thread pool starvation.
[7.378s] [Interop.FunctionalTests.Http3.Http3RequestTests] [Error] Test threw an exception.
Xunit.Sdk.EqualException: Assert.Equal() Failure
              ↓ (pos 4)
Expected: The connection was aborted because the server···
Actual:   The HTTP/2 connection faulted.
              ↑ (pos 4)
   at Xunit.Assert.Equal(String expected, String actual, Boolean ignoreCase, Boolean ignoreLineEndingDifferences, Boolean ignoreWhiteSpaceDifferences) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\StringAsserts.cs:line 244
   at Interop.FunctionalTests.Http3.Http3RequestTests.GET_GracefulServerShutdown_AbortRequestsAfterHostTimeout(HttpProtocols protocol) in /_/src/Servers/Kestrel/test/Interop.FunctionalTests/Http3/Http3RequestTests.cs:line 1545
   at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_1.<<InvokeTestMethodAsync>b__1>d.MoveNext() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\Runners\TestInvoker.cs:line 273
--- End of stack trace from previous location ---
   at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\ExecutionTimer.cs:line 54
   at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 96
[7.398s] [TestLifetime] [Information] Finished test GET_GracefulServerShutdown_AbortRequestsAfterHostTimeout-Http2 in 7.3837468s

Build

https://dev.azure.com/dnceng/public/_build/results?buildId=1590943&view=ms.vss-test-web.build-test-results-tab&runId=44529876&resultId=119172&paneView=debug

[captainsafia]

This issue still persists. Are we sure the test is not asserting for the wrong types?

Assert.IsType() Failure
Expected: Microsoft.AspNetCore.Connections.ConnectionAbortedException
Actual:   System.Net.Quic.QuicOperationAbortedException

   at Interop.FunctionalTests.Http3.Http3RequestTests.GET_GracefulServerShutdown_AbortRequestsAfterHostTimeout(HttpProtocols protocol) in /_/src/Servers/Kestrel/test/Interop.FunctionalTests/Http3/Http3RequestTests.cs:line 1559
--- End of stack trace from previous location ---

It seems to me like something is returning the exception using runtime types instead of our wrappers around them.

Recently failure happened in this run.