Kestrelhttpserver: MemoryPoolBlock.Dispose can throw and ODE during server shutdown leading to an error log from the Socket Transport

[halter73]

MemoryPoolBlock.Dispose() can throw and ODE (ironic I know) during server shutdown leading to an error log from the Socket Transport. Maybe we should to backport https://github.com/aspnet/Common/pull/344/files#diff-708aafde37872ea09e25cfadd4d95f0eL56

This was originally reported by @seanmars in https://github.com/aspnet/KestrelHttpServer/issues/2254#issuecomment-393830106:

When i ctrl+c to close the server it will get exception about "Unexpected exception in SocketConnection.StartAsync"

Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets|Unexpected exception in SocketConnection.StartAsync
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'MemoryPoolBlock'.
   at System.Buffers.ThrowHelper.ThrowObjectDisposedException(ExceptionArgument argument)
   at System.Buffers.MemoryPoolBlock.Dispose()
   at System.IO.Pipelines.BufferSegment.ResetMemory()
   at System.IO.Pipelines.Pipe.CompletePipe()
   at System.IO.Pipelines.Pipe.CompleteWriter(Exception exception)
   at System.IO.Pipelines.Pipe.DefaultPipeWriter.Complete(Exception exception)
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.DoReceive()
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.StartAsync(IConnectionDispatcher connectionDispatcher)

[halter73]

@seanmars What version of the dotnet runtime and Kestrel were you running when you saw this error? Are you able to repro this consistently?

[seanmars]

@halter73 the dotnet --info is below, and it 100% happened when i startup the server and accessed the website and ctrl+c the service immediately, but if i don't close server immediately, i not 100% happen.

.NET Core SDK (reflecting any global.json):
 Version:   2.1.300
 Commit:    adab45bf0c

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.16299
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\2.1.300\

Host (useful for support):
  Version: 2.1.0
  Commit:  caa7b7e2ba

.NET Core SDKs installed:
  1.0.0-preview4-004233 [C:\Program Files\dotnet\sdk]
  1.0.4 [C:\Program Files\dotnet\sdk]
  2.1.104 [C:\Program Files\dotnet\sdk]
  2.1.300 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 1.0.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.6 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs:
  https://aka.ms/dotnet-download

[seanmars]

Hi, I found the point that caused the problem, It's the NLog.
If i use the following script the call the NLog.LogManager.Shutdown(); in the block of finally, it will must happened when i starpup the server and access some api/webview and close server immediately.

But i'm sure that not happened in version 2.0

try
{
    BuildWebHost(args).Build().Run();
}
catch (System.Exception ex)
{
    throw;
}
finally
{
    NLog.LogManager.Shutdown();
}

[muratg]

@seanmars could you please share a simple app that reproduces this problem on GitHub? Thanks.

[0x53A]

I have the same (or a similar) issue: it prints a scary red error, but the exception is caught internally and doesn't actually hurt. It occurs ~90% of the time.

dotnet --info

C:\Users\lr>dotnet --info
.NET Core SDK (reflecting any global.json):
 Version:   2.1.300-rc1-008673
 Commit:    f5e3ddbe73

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.16299
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\2.1.300-rc1-008673\

Host (useful for support):
  Version: 2.1.0-rc1
  Commit:  eb9bc92051

.NET Core SDKs installed:
  1.0.0 [C:\Program Files\dotnet\sdk]
  1.0.2 [C:\Program Files\dotnet\sdk]
  1.0.3 [C:\Program Files\dotnet\sdk]
  1.0.4 [C:\Program Files\dotnet\sdk]
  1.1.0 [C:\Program Files\dotnet\sdk]
  2.1.100-preview-007363 [C:\Program Files\dotnet\sdk]
  2.1.100 [C:\Program Files\dotnet\sdk]
  2.1.101 [C:\Program Files\dotnet\sdk]
  2.1.200-preview-007589 [C:\Program Files\dotnet\sdk]
  2.1.200-preview-007597 [C:\Program Files\dotnet\sdk]
  2.1.200 [C:\Program Files\dotnet\sdk]
  2.1.300-rc1-008673 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.0-rc1-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.0-rc1-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 1.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.1.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.6 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.7 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0-rc1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

To reproduce, run Koala.Tests, it is a console exe.

Example run

[23:54:27 INF] EXPECTO? Running tests... <Expecto>
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
      User profile is available. Using 'C:\Users\lr\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
infoinfoinfo: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
      User profile is available. Using 'C:\Users\lr\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
      User profile is available. Using 'C:\Users\lr\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
      User profile is available. Using 'C:\Users\lr\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
      User profile is available. Using 'C:\Users\lr\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
      User profile is available. Using 'C:\Users\lr\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
      User profile is available. Using 'C:\Users\lr\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:61022/protected
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:61020/api/value
infoinfoinfoinfo: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:61019/api/value
: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:61023/api/value
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:61024/api/value
: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:61025/api/value
: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:61021/api/value
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 97.2491ms 401
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'null'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type '<>f__AnonymousType0`3[[System.Int32, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[System.Double, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]'.
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 125.8125ms 204
infoinfo: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'null'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'null'.
: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 129.0478ms 204
infoinfoinfo: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 129.0475ms 204
: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:61022/protected
: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type '<>f__AnonymousType0`3[[System.Int32, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[System.Double, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]'.
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 0.7498ms 401
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:61022/protected
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 19.2171ms 200 text/plain; charset=utf-8
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'Koala.Tests.TestClass+DataObject'.
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 192.579ms 200 application/xml; charset=utf-8
failfail: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[0]
      Unexpected exception in SocketConnection.StartAsync.
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'MemoryPoolBlock'.
   at System.Buffers.ThrowHelper.ThrowObjectDisposedException(ExceptionArgument argument)
   at System.Buffers.MemoryPoolBlock.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>d__22.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.<StartAsync>d__20.MoveNext()
: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[0]
      Unexpected exception in SocketConnection.StartAsync.
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'MemoryPoolBlock'.
   at System.Buffers.ThrowHelper.ThrowObjectDisposedException(ExceptionArgument argument)
   at System.Buffers.MemoryPoolBlock.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>d__22.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.<StartAsync>d__20.MoveNext()
infoinfo: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 311.9568ms 200 application/json; charset=utf-8
: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 311.8753ms 200 application/json; charset=utf-8
failfail: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[0]
      Unexpected exception in SocketConnection.StartAsync.
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'MemoryPoolBlock'.
   at System.Buffers.ThrowHelper.ThrowObjectDisposedException(ExceptionArgument argument)
   at System.Buffers.MemoryPoolBlock.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>d__22.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.<StartAsync>d__20.MoveNext()
: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[0]
      Unexpected exception in SocketConnection.StartAsync.
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'MemoryPoolBlock'.
   at System.Buffers.ThrowHelper.ThrowObjectDisposedException(ExceptionArgument argument)
   at System.Buffers.MemoryPoolBlock.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>d__22.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.<StartAsync>d__20.MoveNext()
[23:54:28 INF] EXPECTO! 7 tests run in 00:00:01.2202674 for TestClass - 7 passed, 0 ignored, 0 failed, 0 errored. Success! <Expecto>

__It seems to happen when multiple instances of Kestrel are running in parallel. Is this even a supported scenario?__

[seanmars]

@muratg No problem, and i found it's doesn't matter the NLog.LogManager.Shutdown() is called or not.
If the use NLog it is 100% get exception.

https://github.com/seanmars/DotNetCoreObjectDisposedException

[Tragetaschen]

I just got that exception as well, although with a slightly different stack trace (it includes the async state machine, see below) when I CTRL+C'ed my application. I'm running on Mono 5.4.1.6 on Linux. I'm not using any logger besides the default console logger.

By the time I stopped the app, there was one active SignalR connection via WebSocket.

The exception message (including the fail: prefix) is printed seven times. Two of those messages are interleaved. The info: message below is the first message after my app has processed SIGINT.

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 11686.3476ms 101
fail: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[0]
      Unexpected exception in SocketConnection.StartAsync.
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'MemoryPoolBlock'.
  at System.Buffers.ThrowHelper.ThrowObjectDisposedException (System.Buffers.ExceptionArgument argument) [0x00006] in <4a9f78c2c95d4848a0234fc6d3575269>:0
  at System.Buffers.MemoryPoolBlock.Dispose () [0x0000d] in <4a9f78c2c95d4848a0234fc6d3575269>:0
  at System.IO.Pipelines.BufferSegment.ResetMemory () [0x00000] in <15ef00bc425842ceab342d03d837ed41>:0
  at System.IO.Pipelines.Pipe.CompletePipe () [0x0003e] in <15ef00bc425842ceab342d03d837ed41>:0
  at System.IO.Pipelines.Pipe.CompleteWriter (System.Exception exception) [0x00070] in <15ef00bc425842ceab342d03d837ed41>:0
  at System.IO.Pipelines.Pipe+DefaultPipeWriter.Complete (System.Exception exception) [0x00000] in <15ef00bc425842ceab342d03d837ed41>:0
  at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection+<DoReceive>d__22.MoveNext () [0x001f0] in <a7e4f9d63a934612b7d363ff21d11ee0>:0
--- End of stack trace from previous location where exception was thrown ---
  at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <ccc1ca7b16d64c2a80d4b3c13d7667e4>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x0003e] in <ccc1ca7b16d64c2a80d4b3c13d7667e4>:0
  at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in <ccc1ca7b16d64c2a80d4b3c13d7667e4>:0
  at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in <ccc1ca7b16d64c2a80d4b3c13d7667e4>:0
  at System.Runtime.CompilerServices.TaskAwaiter.GetResult () [0x00000] in <ccc1ca7b16d64c2a80d4b3c13d7667e4>:0
  at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection+<StartAsync>d__20.MoveNext () [0x00089] in <a7e4f9d63a934612b7d363ff21d11ee0>:0

[muratg]

@Tratcher @halter73 could one of you pick this up for investigation please? Thanks.

[baal2000]

FYI: getting infrequent reports of this error in our production. In some instances the call stack like in #2254, in others:

 at System.Buffers.ThrowHelper.ThrowObjectDisposedException(ExceptionArgument argument)
 at System.Buffers.MemoryPoolBlock.Dispose()
 at System.IO.Pipelines.BufferSegment.ResetMemory()
 at System.IO.Pipelines.Pipe.CompletePipe()
 at System.IO.Pipelines.Pipe.CompleteReader(Exception exception)
 at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequestsAsync[TContext](IHttpApplication`1 application)

[halter73]

@muratg Should we move this to the 2.1.3 milestone?

I don't think there's too much to investigate. Since so many customers are reporting seeing this, we should backport https://github.com/aspnet/Common/pull/344/files#diff-708aafde37872ea09e25cfadd4d95f0eL56.

Merging #2619 and backporting #2646 should also fix this issue, but I would make all 3 changes to be safe.

[shirhatti]

@halter73 to take this to shiproom

[muratg]

This is approved for 2.1.3.