HttpConnectionMiddleware can call OnConnectionClosed before the transports input writer loop is complete.

[halter73]

HttpConnectionMiddleware can OnConnectionClosed before the transports input writer loop is complete. This can lead to issues where the server disposes the memory pool during shutdown prior to the transport's input writer returning all blocks to the pool leading to test failures like the following:

2018-05-11 11:57:12.588 -07:00 [TestLifetime] [Information] Starting test "WritingToConnectionAfterUnobservedCloseTriggersRequestAbortedToken-http://127.0.0.1:0"
2018-05-11 11:57:12.596 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Hosting starting
2018-05-11 11:57:12.597 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Hosting started
2018-05-11 11:57:12.597 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Loaded hosting startup assembly "Sockets.FunctionalTests, Version=2.2.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60"
2018-05-11 11:57:12.597 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Connection id ""0HLDNE2IVBEIU"" started.
2018-05-11 11:57:12.598 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Information] Request starting HTTP/1.1 POST http:///  8193
2018-05-11 11:57:12.598 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Connection id ""0HLDNE2IVBEIU"" paused.
2018-05-11 11:57:12.598 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Connection id ""0HLDNE2IVBEIU"" resumed.
2018-05-11 11:57:12.599 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Connection id ""0HLDNE2IVBEIU"" paused.
2018-05-11 11:57:12.612 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Connection id ""0HLDNE2IVBEIU"" sending FIN.
2018-05-11 11:57:12.613 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Connection id ""0HLDNE2IVBEIU"" disconnecting.
2018-05-11 11:57:12.623 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Hosting shutdown
2018-05-11 11:57:12.626 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Error] Connection id ""0HLDNE2IVBEIU"", Request id ""0HLDNE2IVBEIU:00000001"": An unhandled exception was thrown by the application.
System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponseStream.ValidateState(CancellationToken cancellationToken) in /Users/shalter/source/aspnet/KestrelHttpServer/src/Kestrel.Core/Internal/Http/HttpResponseStream.cs:line 164
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponseStream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken) in /Users/shalter/source/aspnet/KestrelHttpServer/src/Kestrel.Core/Internal/Http/HttpResponseStream.cs:line 109
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests.<>c__DisplayClass61_0.<<WritingToConnectionAfterUnobservedCloseTriggersRequestAbortedToken>b__6>d.MoveNext() in /Users/shalter/source/aspnet/KestrelHttpServer/test/Kestrel.FunctionalTests/ResponseTests.cs:line 2399
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application) in /Users/shalter/source/aspnet/KestrelHttpServer/src/Kestrel.Core/Internal/Http/HttpProtocol.cs:line 544
   at Xunit.Assert.RecordExceptionAsync(Func`1 testCode) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\Record.cs:line 82
2018-05-11 11:57:12.627 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Information] Request finished in 29.144ms 200 
2018-05-11 11:57:12.627 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Connection id ""0HLDNE2IVBEIU"" stopped.
2018-05-11 11:57:12.627 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Connection id ""0HLDNE2IVBEIU"" resumed.
2018-05-11 11:57:12.631 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Error] Unexpected exception in SocketConnection.StartAsync.
System.InvalidOperationException: Block is being returned to disposed pool
   at System.Buffers.MemoryPoolThrowHelper.ThrowInvalidOperationException_BlockReturnedToDisposedPool(DiagnosticPoolBlock block) in /Users/shalter/.nuget/packages/microsoft.extensions.buffers.memorypool.sources/2.2.0-preview1-34154/contentFiles/cs/netstandard1.0/Microsoft.Extensions.Buffers.MemoryPool.Sources/MemoryPoolThrowHelper.cs:line 52
   at System.Buffers.DiagnosticMemoryPool.Return(DiagnosticPoolBlock block) in /Users/shalter/.nuget/packages/microsoft.extensions.buffers.memorypool.sources/2.2.0-preview1-34154/contentFiles/cs/netstandard1.0/Microsoft.Extensions.Buffers.MemoryPool.Sources/DiagnosticMemoryPool.cs:line 84
   at System.Buffers.DiagnosticPoolBlock.Dispose(Boolean disposing) in /Users/shalter/.nuget/packages/microsoft.extensions.buffers.memorypool.sources/2.2.0-preview1-34154/contentFiles/cs/netstandard1.0/Microsoft.Extensions.Buffers.MemoryPool.Sources/DiagnosticPoolBlock.cs:line 87
   at System.Buffers.MemoryManager`1.System.IDisposable.Dispose()
   at System.IO.Pipelines.BufferSegment.ResetMemory()
   at System.IO.Pipelines.Pipe.CompletePipe()
   at System.IO.Pipelines.Pipe.CompleteWriter(Exception exception)
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.DoReceive() in /Users/shalter/source/aspnet/KestrelHttpServer/src/Kestrel.Transport.Sockets/Internal/SocketConnection.cs:line 144
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.StartAsync() in /Users/shalter/source/aspnet/KestrelHttpServer/src/Kestrel.Transport.Sockets/Internal/SocketConnection.cs:line 75
2018-05-11 11:57:12.631 -07:00 [Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests] [Debug] Server shutdown exception
System.InvalidOperationException: Memory pool with active blocks is being disposed, 6 of 8 returned
   at System.Buffers.MemoryPoolThrowHelper.ThrowInvalidOperationException_DisposingPoolWithActiveBlocks(Int32 returned, Int32 total, DiagnosticPoolBlock[] blocks) in /Users/shalter/.nuget/packages/microsoft.extensions.buffers.memorypool.sources/2.2.0-preview1-34154/contentFiles/cs/netstandard1.0/Microsoft.Extensions.Buffers.MemoryPool.Sources/MemoryPoolThrowHelper.cs:line 62
   at System.Buffers.DiagnosticMemoryPool.Dispose(Boolean disposing) in /Users/shalter/.nuget/packages/microsoft.extensions.buffers.memorypool.sources/2.2.0-preview1-34154/contentFiles/cs/netstandard1.0/Microsoft.Extensions.Buffers.MemoryPool.Sources/DiagnosticMemoryPool.cs:line 119
   at System.Buffers.MemoryPool`1.Dispose()
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.SocketTransport.StopAsync() in /Users/shalter/source/aspnet/KestrelHttpServer/src/Kestrel.Transport.Sockets/SocketTransport.cs:line 142
   at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer.StopAsync(CancellationToken cancellationToken) in /Users/shalter/source/aspnet/KestrelHttpServer/src/Kestrel.Core/KestrelServer.cs:line 198
   at Microsoft.AspNetCore.Hosting.Internal.WebHost.StopAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Hosting.Internal.WebHost.Dispose()

[natemcmaster]

Another test failure: http://aspnetci/viewLog.html?buildId=466377&tab=buildResultsDiv&buildTypeId=Releases_21Public_UbuntuUniverse

[mikeharder]

Another repro in dev: https://ci3.dot.net/job/aspnet_KestrelHttpServer/job/dev/job/linux-Configuration_Release_prtest/270/console

@halter73: Should this be fixed since #2574 has been merged?

[halter73]

That fixed the MemoryPool-related failures and reduced the failures due to ConnectionStop not being called, but there's still a race where ConnectionStop doesn't get logged until after KestrelServer.StopAsync() completes. That's being fixed by this commit as part of #2586 which I hope to merge today. I can split it into another PR if necessary.