search

dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.51k stars 10.04k forks source link

Quarantine GET_GracefulServerShutdown_AbortRequestsAfterHostTimeout #39985

Open Tratcher opened 2 years ago

Tratcher commented 2 years ago

Failing Test(s)

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

```text 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.<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

```text [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.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.<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.<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 commented 2 years ago

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.