Flaky test ClientAbortingConnectionImmediatelyIsNotLoggedHigherThanDebug

[amcasey]

Failing Test(s)

• Microsoft.AspNetCore.Server.Kestrel.Sockets.FunctionalTests.ResponseTests.ClientAbortingConnectionImmediatelyIsNotLoggedHigherThanDebug

Error Message

System.AggregateException : An error occurred while writing to logger(s). (Shutdown failure. Log Debug[NotAllConnectionsClosedGracefully]: Some connections failed to close gracefully during server shutdown. )
---- System.Exception : Shutdown failure. Log Debug[NotAllConnectionsClosedGracefully]: Some connections failed to close gracefully during server shutdown.

Stacktrace

   at Microsoft.Extensions.Logging.Logger.ThrowLoggingError(List`1 exceptions)
   at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.LoggerMessage.<>c__DisplayClass8_0.<Define>g__Log|0(ILogger logger, Exception exception)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.KestrelTrace.ConnectionsLog.NotAllConnectionsClosedGracefully(ILogger logger) in /_/src/Servers/Kestrel/Core/src/Microsoft.Extensions.Logging.Generators/Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator/LoggerMessage.g.cs:line 406
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TransportManager.<>c__DisplayClass16_0.<<StopTransportsAsync>g__StopTransportConnection|0>d.MoveNext() in /_/src/Servers/Kestrel/Core/src/Internal/Infrastructure/TransportManager.cs:line 140
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TransportManager.StopTransportsAsync(List`1 transportsToStop, CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/Infrastructure/TransportManager.cs:line 154
   at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServerImpl.StopAsync(CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/KestrelServerImpl.cs:line 259
   at Microsoft.AspNetCore.Hosting.GenericWebHostService.StopAsync(CancellationToken cancellationToken) in /_/src/Hosting/Hosting/src/GenericHost/GenericWebHostService.cs:line 193
   at Microsoft.Extensions.Hosting.Internal.Host.ForeachService[T](IEnumerable`1 services, CancellationToken token, Boolean concurrent, Boolean abortOnFirstException, List`1 exceptions, Func`3 operation)
   at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.TestServer.DisposeAsync() in /_/src/Servers/Kestrel/shared/test/TransportTestHelpers/TestServer.cs:line 153
   at Microsoft.AspNetCore.Server.Kestrel.Sockets.FunctionalTests.ResponseTests.ClientAbortingConnectionImmediatelyIsNotLoggedHigherThanDebug(ListenOptions listenOptions) in /_/src/Servers/Kestrel/test/FunctionalTests/ResponseTests.cs:line 433
--- End of stack trace from previous location ---
----- Inner Stack Trace -----
   at Microsoft.AspNetCore.InternalTesting.TestApplicationErrorLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter) in /_/src/Servers/Kestrel/shared/test/TestApplicationErrorLogger.cs:line 86
   at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|14_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func`3 formatter, List`1& exceptions, TState& state)

Logs

2023-11-29T20:53:47.2860210Z  | [0.006s] TestLifetime Information: Starting test ClientAbortingConnectionImmediatelyIsNotLoggedHigherThanDebug-http_127.0.0.1_56248 at 2023-11-29T20:53:15
2023-11-29T20:53:47.2860260Z  | [0.008s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting starting
2023-11-29T20:53:47.2860290Z  | [0.009s] Microsoft.Hosting.Lifetime Information: Now listening on: http://127.0.0.1:56248
2023-11-29T20:53:47.2860330Z  | [0.009s] Microsoft.AspNetCore.Hosting.Diagnostics Debug: Loaded hosting startup assembly Sockets.FunctionalTests
2023-11-29T20:53:47.2860360Z  | [0.009s] Microsoft.Hosting.Lifetime Information: Application started. Press Ctrl+C to shut down.
2023-11-29T20:53:47.2860390Z  | [0.009s] Microsoft.Hosting.Lifetime Information: Hosting environment: Production
2023-11-29T20:53:47.2860490Z  | [0.009s] Microsoft.Hosting.Lifetime Information: Content root path: /private/tmp/helix/working/95D9082A/w/B47809C9/e/
2023-11-29T20:53:47.2860530Z  | [0.009s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting started
2023-11-29T20:53:47.2860560Z  | [0.009s] Microsoft.AspNetCore.Server.Kestrel Debug: TestServer is listening on port 56248
2023-11-29T20:53:47.2860600Z  | [0.015s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting stopping
2023-11-29T20:53:47.2860630Z  | [0.015s] Microsoft.Hosting.Lifetime Information: Application is shutting down...
2023-11-29T20:53:47.2860670Z  | [0.026s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HMVH3KL9U7EB" accepted.
2023-11-29T20:53:47.2860700Z  | [0.027s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HMVH3KL9U7EB" started.
2023-11-29T20:53:47.2860740Z  | [30.120s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Some connections failed to close gracefully during server shutdown.
2023-11-29T20:53:47.2860770Z  | [30.123s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting shutdown exception
2023-11-29T20:53:47.2860880Z  | System.AggregateException: An error occurred while writing to logger(s). (Shutdown failure. Log Debug[NotAllConnectionsClosedGracefully]: Some connections failed to close gracefully during server shutdown. )
2023-11-29T20:53:47.2860930Z  |  ---> System.Exception: Shutdown failure. Log Debug[NotAllConnectionsClosedGracefully]: Some connections failed to close gracefully during server shutdown. 
2023-11-29T20:53:47.2860960Z  |    at Microsoft.AspNetCore.InternalTesting.TestApplicationErrorLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter) in /_/src/Servers/Kestrel/shared/test/TestApplicationErrorLogger.cs:line 86
2023-11-29T20:53:47.2861030Z  |    at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|14_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func`3 formatter, List`1& exceptions, TState& state)
2023-11-29T20:53:47.2861070Z  |    --- End of inner exception stack trace ---
2023-11-29T20:53:47.2861100Z  |    at Microsoft.Extensions.Logging.Logger.ThrowLoggingError(List`1 exceptions)
2023-11-29T20:53:47.2861140Z  |    at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
2023-11-29T20:53:47.2861170Z  |    at Microsoft.Extensions.Logging.LoggerMessage.<>c__DisplayClass8_0.<Define>g__Log|0(ILogger logger, Exception exception)
2023-11-29T20:53:47.2861260Z  |    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.KestrelTrace.ConnectionsLog.NotAllConnectionsClosedGracefully(ILogger logger) in /_/src/Servers/Kestrel/Core/src/Microsoft.Extensions.Logging.Generators/Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator/LoggerMessage.g.cs:line 406
2023-11-29T20:53:47.2861340Z  |    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TransportManager.<>c__DisplayClass16_0.<<StopTransportsAsync>g__StopTransportConnection|0>d.MoveNext() in /_/src/Servers/Kestrel/Core/src/Internal/Infrastructure/TransportManager.cs:line 140
2023-11-29T20:53:47.2861410Z  | --- End of stack trace from previous location ---
2023-11-29T20:53:47.2861450Z  |    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TransportManager.StopTransportsAsync(List`1 transportsToStop, CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/Infrastructure/TransportManager.cs:line 154
2023-11-29T20:53:47.2861570Z  |    at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServerImpl.StopAsync(CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/KestrelServerImpl.cs:line 259
2023-11-29T20:53:47.2861610Z  |    at Microsoft.AspNetCore.Hosting.GenericWebHostService.StopAsync(CancellationToken cancellationToken) in /_/src/Hosting/Hosting/src/GenericHost/GenericWebHostService.cs:line 193
2023-11-29T20:53:47.2861650Z  |    at Microsoft.Extensions.Hosting.Internal.Host.ForeachService[T](IEnumerable`1 services, CancellationToken token, Boolean concurrent, Boolean abortOnFirstException, List`1 exceptions, Func`3 operation)
2023-11-29T20:53:47.2861680Z  | [30.132s] Microsoft.AspNetCore.Server.Kestrel.Sockets.FunctionalTests.ResponseTests Error: Test threw an exception.
2023-11-29T20:53:47.2861720Z  | System.AggregateException: An error occurred while writing to logger(s). (Shutdown failure. Log Debug[NotAllConnectionsClosedGracefully]: Some connections failed to close gracefully during server shutdown. )
2023-11-29T20:53:47.2861750Z  |  ---> System.Exception: Shutdown failure. Log Debug[NotAllConnectionsClosedGracefully]: Some connections failed to close gracefully during server shutdown. 
2023-11-29T20:53:47.2861850Z  |    at Microsoft.AspNetCore.InternalTesting.TestApplicationErrorLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter) in /_/src/Servers/Kestrel/shared/test/TestApplicationErrorLogger.cs:line 86
2023-11-29T20:53:47.2861920Z  |    at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|14_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func`3 formatter, List`1& exceptions, TState& state)
2023-11-29T20:53:47.2861960Z  |    --- End of inner exception stack trace ---
2023-11-29T20:53:47.2861990Z  |    at Microsoft.Extensions.Logging.Logger.ThrowLoggingError(List`1 exceptions)
2023-11-29T20:53:47.2862040Z  |    at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
2023-11-29T20:53:47.2862070Z  |    at Microsoft.Extensions.Logging.LoggerMessage.<>c__DisplayClass8_0.<Define>g__Log|0(ILogger logger, Exception exception)
2023-11-29T20:53:47.2862170Z  |    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.KestrelTrace.ConnectionsLog.NotAllConnectionsClosedGracefully(ILogger logger) in /_/src/Servers/Kestrel/Core/src/Microsoft.Extensions.Logging.Generators/Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator/LoggerMessage.g.cs:line 406
2023-11-29T20:53:47.2862250Z  |    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TransportManager.<>c__DisplayClass16_0.<<StopTransportsAsync>g__StopTransportConnection|0>d.MoveNext() in /_/src/Servers/Kestrel/Core/src/Internal/Infrastructure/TransportManager.cs:line 140
2023-11-29T20:53:47.2862320Z  | --- End of stack trace from previous location ---
2023-11-29T20:53:47.2862360Z  |    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TransportManager.StopTransportsAsync(List`1 transportsToStop, CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/Infrastructure/TransportManager.cs:line 154
2023-11-29T20:53:47.2862420Z  |    at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServerImpl.StopAsync(CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/KestrelServerImpl.cs:line 259
2023-11-29T20:53:47.2862460Z  |    at Microsoft.AspNetCore.Hosting.GenericWebHostService.StopAsync(CancellationToken cancellationToken) in /_/src/Hosting/Hosting/src/GenericHost/GenericWebHostService.cs:line 193
2023-11-29T20:53:47.2862550Z  |    at Microsoft.Extensions.Hosting.Internal.Host.ForeachService[T](IEnumerable`1 services, CancellationToken token, Boolean concurrent, Boolean abortOnFirstException, List`1 exceptions, Func`3 operation)
2023-11-29T20:53:47.2862590Z  |    at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken)
2023-11-29T20:53:47.2862620Z  |    at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.TestServer.DisposeAsync() in /_/src/Servers/Kestrel/shared/test/TransportTestHelpers/TestServer.cs:line 153
2023-11-29T20:53:47.2862660Z  |    at Microsoft.AspNetCore.Server.Kestrel.Sockets.FunctionalTests.ResponseTests.ClientAbortingConnectionImmediatelyIsNotLoggedHigherThanDebug(ListenOptions listenOptions) in /_/src/Servers/Kestrel/test/FunctionalTests/ResponseTests.cs:line 433
2023-11-29T20:53:47.2862730Z  |    at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_0.<<InvokeTestMethodAsync>b__1>d.MoveNext() in /_/src/xunit.execution/Sdk/Frameworks/Runners/TestInvoker.cs:line 264
2023-11-29T20:53:47.2862760Z  | --- End of stack trace from previous location ---
2023-11-29T20:53:47.2862840Z  |    at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in /_/src/xunit.execution/Sdk/Frameworks/ExecutionTimer.cs:line 48
2023-11-29T20:53:47.2862880Z  |    at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in /_/src/xunit.core/Sdk/ExceptionAggregator.cs:line 90
2023-11-29T20:53:47.2862920Z  | [30.133s] TestLifetime Information: Finished test ClientAbortingConnectionImmediatelyIsNotLoggedHigherThanDebug-http_127.0.0.1_56248 in 30.1272253s

Build

https://dev.azure.com/dnceng-public/public/_build/results?buildId=484090

[amcasey]

Note that the linked build is for a PR that removes the test from the helix retry list and repeats the flaky test 100 times.

[amcasey]

If we decide that flakiness is acceptable, unquarantine the test, add a comment explaining what makes it flaky, and ensure it's in the helix retry list.