marcinbudny / applicationinsights-owinextensions

MIT License
47 stars 15 forks source link

Under Load we see this exception #20

Closed sabryguen closed 3 years ago

sabryguen commented 7 years ago

System.OperationCanceledException: at System.Threading.CancellationToken.ThrowOperationCanceledException (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Web.Http.Owin.HttpMessageHandlerAdapter+d13.MoveNext (System.Web.Http.Owin, Version=5.2.3.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35) at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Web.Http.Owin.HttpMessageHandlerAdapter+d0.MoveNext (System.Web.Http.Owin, Version=5.2.3.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35) at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at ApplicationInsights.OwinExtensions.HttpRequestTrackingMiddleware+d__4.MoveNext (ApplicationInsights.OwinExtensions, Version=0.4.1.0, Culture=neutral, PublicKeyToken=null)

marcinbudny commented 7 years ago

Hi, Are you using getContextProperties delegate in order to extract additional information from request? If so, then what is that you do exactly?

borys86 commented 7 years ago

hi Marcin, https://www.blogger.com/comment.g?blogID=4923273354692358330&postID=2036195216408138414&page=1&token=1500908631925 as in my post there, this looks same and is also happening under high load.

borys86 commented 7 years ago

For a reference I will paste my exception here too: System.OperationCanceledException: at System.Threading.CancellationToken.ThrowOperationCanceledException (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Web.Http.Owin.HttpMessageHandlerAdapter+d__20.MoveNext (System.Web.Http.Owin, Version=5.2.3.0, ... at System.Web.Http.Owin.HttpMessageHandlerAdapter+d__0.MoveNext (System.Web.Http.Owin, Version=5.2.3.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35) at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at ApplicationInsights.OwinExtensions.RestoreOperationIdContextMiddleware+d__1.MoveNext (ApplicationInsights.OwinExtensions, Version=0.4.1.0, Culture=neutral, PublicKeyToken=null) at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContextStage+d__5.MoveNext (Microsoft.Owin.Host.SystemWeb, Version=3.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35) at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at Microsoft.Owin.Security.Infrastructure.AuthenticationMiddleware1+d0.MoveNext (Microsoft.Owin.Security, Version=3.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35) at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at IdentityServer3.AccessTokenValidation.IdentityServerBearerTokenValidationMiddleware+d8.MoveNext (IdentityServer3.AccessTokenValidation, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null) at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089) at ApplicationInsights.OwinExtensions.HttpRequestTrackingMiddleware+d__4.MoveNext (ApplicationInsights.OwinExtensions, Version=0.4.1.0, Culture=neutral, PublicKeyToken=null) `

borys86 commented 7 years ago

Hi. The answer is that this exception in AI was thrown because of the IIS worker client disconnected exception. Because of that app was not able to read request info and was thrown Operation canceled exception.

marcinbudny commented 7 years ago

Some research I did on SO also suggests this may be related to client prematurely disconnecting. However I was not able to reproduce these conditions on my machine. I'm going to leave this issue open for a while, maybe someone will be able to provide more information.

SashaPshenychniy commented 4 years ago

Same exception occurs in 2020 with version 0.6.0.

UPDATE: Pattern is similar to described below, but exact numbers could be exaggerated due to Azure AppInsights sampling and estimating exceptions count based on samples. I can clearly see 1-4 consequtive samples within few seconds. UPDATE 2: Found a point which cannot be explained with sampling: thousands of exceptions per minute: image

The pattern is that exceptions occur in batches: it can be many days with no exceptions, and then boom: couple of hundred exceptions in just a few minutes (1-2 minute spikes usually). And then back to normal behavior (0-exception) for some time, and again boom - hundreds of exceptions per minute.

image

image

Strange correlation with CPU load discovered: image Although there might be 3rd factor influencing both correlating parameters (e.g. requests count, although it didn't grow that much): image

marcinbudny commented 4 years ago

I can confirm with high probability this exception is thrown when the client cancels the request. If I find some time, I will implement some handling logic for this in http request middleware.

SashaPshenychniy commented 4 years ago

Thanks for quick reply, @marcinbudny ! A collegue of mine also told they had this issue due to client timeout. And many failing requests indeed are long-running (up to couple of minutes). But at the same time there are some requests which fail in just miliseconds (even 8ms).

marcinbudny commented 4 years ago

Version 0.8.0 will now by default filter OperationCancelledException when the current request is marked as cancelled.

marcinbudny commented 4 years ago

The 0.8.0 fix may also solve the problem with ObjectDisposedException that I wasn't able to reproduce. If you experienced this problem, please let me know.

SashaPshenychniy commented 4 years ago

Thank you so much for the fix, @marcinbudny ! We'll update to the latest version and check how it works.

marcinbudny commented 3 years ago

Closing due to lack of activity