Abort gracefully closes the response rather than aborting it

[BrennanConroy]

Assert.DoesNotContain() Failure
Found:    (filter expression)
In value: ConcurrentQueue<WriteContext> [WriteContext { EventId = 0, Exception = null, Formatter = Func3 { ... }, LoggerName = "Microsoft.AspNetCore.Server.IIS.FunctionalTests.Te"..., LogLevel = Debug, ... }, WriteContext { EventId = Starting, Exception = null, Formatter = Func3 { ... }, LoggerName = "Microsoft.Extensions.Hosting.Internal.Host", LogLevel = Debug, ... }, WriteContext { EventId = HostingStartupAssemblyLoaded, Exception = null, Formatter = Func3 { ... }, LoggerName = "Microsoft.AspNetCore.Hosting.Diagnostics", LogLevel = Debug, ... }, WriteContext { EventId = 0, Exception = null, Formatter = Func3 { ... }, LoggerName = "Microsoft.Hosting.Lifetime", LogLevel = Information, ... }, WriteContext { EventId = 0, Exception = null, Formatter = Func`3 { ... }, LoggerName = "Microsoft.Hosting.Lifetime", LogLevel = Information, ... }, ...]

at Microsoft.AspNetCore.Server.IIS.FunctionalTests.StrictTestServerTests.Dispose() in /_/src/Servers/IIS/IIS/test/IIS.Tests/StrictTestServerTests.cs:line 17
   at ReflectionAbstractionExtensions.DisposeTestClass(ITest test, Object testClass, IMessageBus messageBus, ExecutionTimer timer, CancellationTokenSource cancellationTokenSource) in C:\Dev\xunit\xunit\src\xunit.execution\Extensions\ReflectionAbstractionExtensions.cs:line 79

Logs

[0.001s] [TestLifetime] [Information] Starting test ClosesAfterDataSent at 2021-03-30T06:36:31
[6.836s] [Microsoft.AspNetCore.Server.IIS.FunctionalTests.TestServer] [Debug] Method: GET, RequestUri: 'http://localhost:58030/start', Version: 1.1, Content: <null>, Headers:
{
}
[6.839s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting starting
[6.839s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Debug] Loaded hosting startup assembly IIS.Tests
[6.840s] [Microsoft.Hosting.Lifetime] [Information] Application started. Press Ctrl+C to shut down.
[6.840s] [Microsoft.Hosting.Lifetime] [Information] Hosting environment: Production
[6.840s] [Microsoft.Hosting.Lifetime] [Information] Content root path: C:\h\w\B64C0933\w\AE29096B\e\.
[6.840s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting started
[6.840s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request starting HTTP/1.1 GET http://localhost:58030/start - -
[6.841s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request finished HTTP/1.1 GET http://localhost:58030/start - - - 200 - - 0.3827ms
[6.841s] [Microsoft.AspNetCore.Server.IIS.FunctionalTests.TestServer] [Debug] StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Server: Microsoft-IIS/10.0
  Date: Tue, 30 Mar 2021 06:36:37 GMT
  Content-Length: 4
}
[6.841s] [Microsoft.AspNetCore.Server.IIS.FunctionalTests.TestServer] [Debug] Done
[6.843s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request starting HTTP/1.1 POST http://localhost/ - 1
[6.966s] [Microsoft.Hosting.Lifetime] [Information] Application is shutting down...
[7.523s] [Microsoft.AspNetCore.Server.IIS.Core.IISHttpServer] [Error] Connection ID "18086456105130524677", Request ID "80000006-0000-fb00-b63f-84710c7967bb": An unhandled exception was thrown by the application.
System.Runtime.InteropServices.COMException (0x80070006): The handle is invalid. (0x80070006 (E_HANDLE))
   at Microsoft.AspNetCore.Server.IIS.NativeMethods.Validate(Int32 hr) in /_/src/Servers/IIS/IIS/src/NativeMethods.cs:line 331
   at Microsoft.AspNetCore.Server.IIS.NativeMethods.HttpTryCancelIO(NativeSafeHandle pInProcessHandler) in /_/src/Servers/IIS/IIS/src/NativeMethods.cs:line 280
   at Microsoft.AspNetCore.Server.IIS.Core.IO.AsyncIOEngine.Complete() in /_/src/Servers/IIS/IIS/src/Core/IO/AsyncIOEngine.cs:line 148
   at Microsoft.AspNetCore.Server.IIS.Core.IISHttpContextOfT`1.ProcessRequestAsync() in /_/src/Servers/IIS/IIS/src/Core/IISHttpContextOfT.cs:line 95
[7.523s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request finished HTTP/1.1 POST http://localhost/ - 1 - 200 - - 680.6435ms
[9.058s] [TestLifetime] [Information] Finished test ClosesAfterDataSent in 9.0567293s

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

Thanks for contacting us.
We're moving this issue to the Next sprint planning milestone for future evaluation / consideration. Because it's not immediately obvious that this is a bug in our framework, we would like to keep this around to collect more feedback, which can later help us determine the impact of it. We will re-evaluate this issue, during our next planning meeting(s).
If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues.
To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

[Tratcher]

30 day stats: 22 failures out of 74 runs, 60% pass rate.

Current error:

System.AggregateException : One or more errors occurred. (Expected connection close, received data instead: "0

") (Unexpected log: Error Microsoft.AspNetCore.Server.IIS.FunctionalTests.ResponseAbortTests: Test threw an exception.)
---- System.IO.IOException : Expected connection close, received data instead: "0

"
---- Unexpected log: Error Microsoft.AspNetCore.Server.IIS.FunctionalTests.ResponseAbortTests: Test threw an exception.

----- Inner Stack Trace #1 (System.IO.IOException) -----
   at Microsoft.AspNetCore.Server.IIS.FunctionalTests.ResponseAbortTests.ClosesAfterDataSent() in /_/src/Servers/IIS/IIS/test/IIS.Tests/ResponseAbortTests.cs:line 59
--- End of stack trace from previous location ---
----- Inner Stack Trace #2 (Xunit.Sdk.XunitException) -----
   at Microsoft.AspNetCore.Server.IIS.FunctionalTests.StrictTestServerTests.Dispose() in /_/src/Servers/IIS/IIS/test/IIS.Tests/StrictTestServerTests.cs:line 22
   at ReflectionAbstractionExtensions.DisposeTestClass(ITest test, Object testClass, IMessageBus messageBus, ExecutionTimer timer, CancellationTokenSource cancellationTokenSource) in C:\Dev\xunit\xunit\src\xunit.execution\Extensions\ReflectionAbstractionExtensions.cs:line 79

[0.009s] [TestLifetime] [Information] Starting test ClosesAfterDataSent at 2021-05-08T18:48:51
[2.695s] [Microsoft.AspNetCore.Server.IIS.FunctionalTests.TestServer] [Debug] Method: GET, RequestUri: 'http://localhost:49983/start', Version: 1.1, Content: <null>, Headers:
{
}
[2.699s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting starting
[2.700s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Debug] Loaded hosting startup assembly IIS.Tests
[2.700s] [Microsoft.Hosting.Lifetime] [Information] Application started. Press Ctrl+C to shut down.
[2.700s] [Microsoft.Hosting.Lifetime] [Information] Hosting environment: Production
[2.700s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request starting HTTP/1.1 GET http://localhost:49983/start - -
[2.701s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request finished HTTP/1.1 GET http://localhost:49983/start - - - 200 - - 0.6401ms
[2.701s] [Microsoft.AspNetCore.Server.IIS.FunctionalTests.TestServer] [Debug] StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Server: Microsoft-IIS/8.5
  Date: Sat, 08 May 2021 18:48:53 GMT
  Content-Length: 4
}
[2.700s] [Microsoft.Hosting.Lifetime] [Information] Content root path: C:\h\w\B9BA09A9\w\BA650A14\e\.
[2.701s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting started
[2.701s] [Microsoft.AspNetCore.Server.IIS.FunctionalTests.TestServer] [Debug] Done
[2.704s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request starting HTTP/1.1 POST http://localhost/ - 1
[2.711s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request finished HTTP/1.1 POST http://localhost/ - 1 - 200 - - 6.8874ms
[2.825s] [Microsoft.Hosting.Lifetime] [Information] Application is shutting down...
[4.903s] [Microsoft.AspNetCore.Server.IIS.FunctionalTests.ResponseAbortTests] [Error] Test threw an exception.
System.IO.IOException: Expected connection close, received data instead: "0

"
   at Microsoft.AspNetCore.Server.IIS.FunctionalTests.ResponseAbortTests.ClosesAfterDataSent() in /_/src/Servers/IIS/IIS/test/IIS.Tests/ResponseAbortTests.cs:line 59
   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 264
--- 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 48
   at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 90
[4.903s] [TestLifetime] [Information] Finished test ClosesAfterDataSent in 4.9008712s

[Tratcher]

This test is now failing 100% since 7/27. @halter73 that aligns with your change here:
33c24dc#diff-54519d7cd867fb07d7e96dd65385bce7f3f7647bac3aa66ad2f7a34120fe17f6

Any idea why that would impact Abort?

[Tratcher]

Still failing 100%, same error.

[Tratcher]

Still failing 100%, same error.

[Tratcher]

Still failing 100%

System.IO.IOException : Expected connection close, received data instead: "0

"

Is that just a chunked terminator? Oh, the test was supposed to abort the connection rather than close gracefully.

[Tratcher]

On further investigation this is a product bug that can cause unreported response truncation of chunked responses (E.g. data corruption).

Here's the flow:

aspnetcore/src/Servers/IIS/IIS/src/Core/IISHttpContext.IO.cs

Lines 277 to 284 in b9fcd82

	public void Abort(Exception reason)
	{
	_bodyOutput.Abort(reason);
	_streams.Abort(reason);
	NativeMethods.HttpCloseConnection(_requestNativeHandle);
	AbortIO(clientDisconnect: false);
	}

IISHttpContext.Abort ->
OuputProducer.Abort ->
_pipe.Writer.Complete() (without an error)

aspnetcore/src/Servers/IIS/IIS/src/Core/IISHttpContext.IO.cs

Lines 153 to 180 in b9fcd82

	private async Task WriteBody(bool flush = false)
	{
	Exception? error = null;
	try
	{
	while (true)
	{
	var result = await _bodyOutput.Reader.ReadAsync();
	var buffer = result.Buffer;
	try
	{
	if (!buffer.IsEmpty)
	{
	await AsyncIO!.WriteAsync(buffer);
	}
	// if request is done no need to flush, http.sys would do it for us
	if (result.IsCompleted)
	{
	// When is the reader completed? Is it always after the request pipeline exits? Or can CompleteAsync make it complete early?
	if (HasTrailers)
	{
	SetResponseTrailers();
	}
	// Done with response, say there is no more data after writing trailers.
	await AsyncIO!.FlushAsync(moreData: false);

WriteBody wakes up and decides the pipe is complete so it gracefully closes the response. There's no check in WriteBody that the response was aborted.

Later Abort calls HttpCloseConnection to actually abort the connection, but the chunked terminator has already been incorrectly sent so the client can't tell the response aborted abnormally.

Changing Abort to call HttpCloseConnection first does fix the test, but I think there are side-effects where that causes write errors. A more correct fix would probably be for OutputProducer to complete the response body pipe with an error so it knows not to gracefully close the response.