Skip to content
This repository was archived by the owner on Dec 18, 2018. It is now read-only.

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

Closed
halter73 opened this issue Jun 1, 2018 · 12 comments
Labels
3 - Done investigate Investigation item SHP: Approved Shiproom has approved the issue
Milestone

Comments

@halter73
Copy link
Member

halter73 commented Jun 1, 2018

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 #2254 (comment):

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
Copy link
Member Author

halter73 commented Jun 1, 2018

@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
Copy link

seanmars commented Jun 2, 2018

@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
Copy link

seanmars commented Jun 4, 2018

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
Copy link
Contributor

muratg commented Jun 4, 2018

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

@0x53A
Copy link

0x53A commented Jun 4, 2018

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
Copy link

seanmars commented Jun 5, 2018

@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
Copy link
Contributor

Tragetaschen commented Jun 5, 2018

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
Copy link
Contributor

muratg commented Jun 5, 2018

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

@baal2000
Copy link

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
Copy link
Member Author

@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.

@muratg muratg modified the milestones: 2.2.0, 2.1.3 Jun 12, 2018
@shirhatti shirhatti added the SHP: Approval pending Shiproom approval is required for the issue label Jun 15, 2018
@shirhatti
Copy link

@halter73 to take this to shiproom

@muratg muratg added SHP: Approved Shiproom has approved the issue and removed SHP: Approval pending Shiproom approval is required for the issue labels Jun 19, 2018
@muratg
Copy link
Contributor

muratg commented Jun 19, 2018

This is approved for 2.1.3.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
3 - Done investigate Investigation item SHP: Approved Shiproom has approved the issue
Projects
None yet
Development

No branches or pull requests

7 participants