Handle and log OperationCanceledExceptions thrown due to client disconnects

[halter73]

From @anpete on April 14, 2016 5:32

Not sure if this is expected, so filing just in case. While investigating our internal MusicStore stress scenario I'm seeing an OperationCanceledException raised occasionally when the number of clients > ~50.

Stack:

fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[0]
      An unhandled exception has occurred: The operation was canceled.
System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at Microsoft.AspNetCore.Http.Extensions.StreamCopyOperation.<CopyToAsync>d__1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.StaticFiles.StaticFileContext.<SendAsync>d__46.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Session.SessionMiddleware.<Invoke>d__8.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Session.SessionMiddleware.<Invoke>d__8.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>d__6.MoveNext()
warn: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[0]
      The response has already started, the error handler will not be executed.
fail: Microsoft.AspNetCore.Server.Kestrel[13]
      Connection id "0HKR44KL0RBVP": An unhandled exception was thrown by the application.
System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at Microsoft.AspNetCore.Http.Extensions.StreamCopyOperation.<CopyToAsync>d__1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.StaticFiles.StaticFileContext.<SendAsync>d__46.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Session.SessionMiddleware.<Invoke>d__8.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Session.SessionMiddleware.<Invoke>d__8.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware.<Invoke>d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.<Invoke>d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Server.Kestrel.Http.Frame`1.<RequestProcessingAsync>d__2.MoveNext()

Copied from original issue: aspnet/KestrelHttpServer#748

[Tratcher]

@halter73 what happened to all the comments?

[halter73]

They're in the old issue. Would you prefer I close this and reopen with comments?

[Tratcher]

Or re-word this one to explain the proposal

[halter73]

Ideally the client disconnect log message would have a LogLevel lower than error, since the main motivation for this issue is to clean up logs. I would go with LogLevel.Information, since that is how Kestrel logs most connection errors. It might also be helpful to indicate what file was being served.

[gdoron]

I personally think it should be debug.
There is no information an application owner should care about except from debugging nor there's an action he should or even can do.
It's completely out of scope of applications.
(Unlike timing for example)

[Tratcher]

The other thing to sort out here is OperationCancelledException vs TaskCanceledException. Kestrel uses the former and WebListener the later.

[halter73]

@Tratcher Did you mean that Kestrel uses the latter TaskCanceledException? I don't think Kestrel uses OperationCanceledException anywhere.

[Tratcher]

The OperationCanceledException may be coming directly from StreamCopyOperation

[Tratcher]

TaskCanceledException derives from OperationCanceledException, so anything that deals with OCE will also handle TCE

[halter73]

Sure, but anything that Kestrel throws directly will be the derived type.

[gdoron]

If I understood the code correctly, you ended up making the log debug as I suggested, right?

[Tratcher]

Yes bbf1478#diff-991aec26255237cd6dbfa787d0995a2aR85