Possible deadlock in access token retrieval?

[sixten]

We moved our IdentityServer-based user management service into production a couple of months ago. All was well until a few weeks ago, when we started to see a strange situation: the site will stop responding, and start throwing lots of exception as it exhausts its database connection pool. The web server and the SQL Server meantime are performing close to normally. After some period of time in this state (10-90 minutes), it will suddenly unblock, and start working normally again.

We've grabbed thread dumps of the app pool a couple of times when this has happened, and the stack traces end up overwhelmingly stuck waiting for the results of the client lookup that happens in the middle of processing an access token validation request. In the dump we took the other day, 638 of 674 threads had this same following trace. (Note that we're still running v1.6.1: we were deep in final testing of this stuff when you released v2. But none of this functionality seems to have changed much.)

[[GCFrame]] 
[[HelperMethodFrame_1OBJ] (System.Threading.Monitor.ObjWait)] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object) 
mscorlib_ni!System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken)+3ec 
mscorlib_ni!System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken)+db 
mscorlib_ni!System.Threading.Tasks.Task.InternalWait(Int32, System.Threading.CancellationToken)+24a 
mscorlib_ni!System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task)+d6fd50 
mscorlib_ni!System.Runtime.CompilerServices.TaskAwaiter`1[[System.__Canon, mscorlib]].GetResult()+31 
Thinktecture.IdentityServer.EntityFramework.Serialization.AsyncHelper.RunSync[[System.__Canon, mscorlib]](System.Func`1>)+ef 
Thinktecture.IdentityServer.EntityFramework.Serialization.ClientConverter.ReadJson(Newtonsoft.Json.JsonReader, System.Type, System.Object, Newtonsoft.Json.JsonSerializer)+7b 
Newtonsoft.Json.Serialization.JsonSerializerInternalReader.DeserializeConvertable(Newtonsoft.Json.JsonConverter, Newtonsoft.Json.JsonReader, System.Type, System.Object)+18c 
Newtonsoft.Json.Serialization.JsonSerializerInternalReader.SetPropertyValue(Newtonsoft.Json.Serialization.JsonProperty, Newtonsoft.Json.JsonConverter, Newtonsoft.Json.Serialization.JsonContainerContract, Newtonsoft.Json.Serialization.JsonProperty, Newtonsoft.Json.JsonReader, System.Object)+131 
Newtonsoft.Json.Serialization.JsonSerializerInternalReader.PopulateObject(System.Object, Newtonsoft.Json.JsonReader, Newtonsoft.Json.Serialization.JsonObjectContract, Newtonsoft.Json.Serialization.JsonProperty, System.String)+5ff 
Newtonsoft.Json.Serialization.JsonSerializerInternalReader.CreateObject(Newtonsoft.Json.JsonReader, System.Type, Newtonsoft.Json.Serialization.JsonContract, Newtonsoft.Json.Serialization.JsonProperty, Newtonsoft.Json.Serialization.JsonContainerContract, Newtonsoft.Json.Serialization.JsonProperty, System.Object)+357 
Newtonsoft.Json.Serialization.JsonSerializerInternalReader.CreateValueInternal(Newtonsoft.Json.JsonReader, System.Type, Newtonsoft.Json.Serialization.JsonContract, Newtonsoft.Json.Serialization.JsonProperty, Newtonsoft.Json.Serialization.JsonContainerContract, Newtonsoft.Json.Serialization.JsonProperty, System.Object)+bc 
Newtonsoft.Json.Serialization.JsonSerializerInternalReader.SetPropertyValue(Newtonsoft.Json.Serialization.JsonProperty, Newtonsoft.Json.JsonConverter, Newtonsoft.Json.Serialization.JsonContainerContract, Newtonsoft.Json.Serialization.JsonProperty, Newtonsoft.Json.JsonReader, System.Object)+174 
Newtonsoft.Json.Serialization.JsonSerializerInternalReader.PopulateObject(System.Object, Newtonsoft.Json.JsonReader, Newtonsoft.Json.Serialization.JsonObjectContract, Newtonsoft.Json.Serialization.JsonProperty, System.String)+5ff 
Newtonsoft.Json.Serialization.JsonSerializerInternalReader.CreateObject(Newtonsoft.Json.JsonReader, System.Type, Newtonsoft.Json.Serialization.JsonContract, Newtonsoft.Json.Serialization.JsonProperty, Newtonsoft.Json.Serialization.JsonContainerContract, Newtonsoft.Json.Serialization.JsonProperty, System.Object)+357 
Newtonsoft.Json.Serialization.JsonSerializerInternalReader.CreateValueInternal(Newtonsoft.Json.JsonReader, System.Type, Newtonsoft.Json.Serialization.JsonContract, Newtonsoft.Json.Serialization.JsonProperty, Newtonsoft.Json.Serialization.JsonContainerContract, Newtonsoft.Json.Serialization.JsonProperty, System.Object)+bc 
Newtonsoft.Json.Serialization.JsonSerializerInternalReader.Deserialize(Newtonsoft.Json.JsonReader, System.Type, Boolean)+1a8 
Newtonsoft.Json.JsonSerializer.DeserializeInternal(Newtonsoft.Json.JsonReader, System.Type)+125 
Newtonsoft.Json.JsonConvert.DeserializeObject(System.String, System.Type, Newtonsoft.Json.JsonSerializerSettings)+112 
Newtonsoft.Json.JsonConvert.DeserializeObject[[System.__Canon, mscorlib]](System.String, Newtonsoft.Json.JsonSerializerSettings)+39 
Thinktecture.IdentityServer.EntityFramework.BaseTokenStore`1+d__0[[System.__Canon, mscorlib]].MoveNext()+2d5 
mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+285 
mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+9 
mscorlib_ni!System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()+a4 
System_Web_ni!System.Web.Util.SynchronizationHelper.SafeWrapCallback(System.Action)+b3 
mscorlib_ni!System.Threading.Tasks.Task.Execute()+6e 
mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+285 
mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+9 
mscorlib_ni!System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)+2c5 
mscorlib_ni!System.Threading.Tasks.Task.ExecuteEntry(Boolean)+85 
mscorlib_ni!System.Threading.ThreadPoolWorkQueue.Dispatch()+1ea 
[[DebuggerU2MCatchHandlerFrame]] 
[[ContextTransitionFrame]] 
[[DebuggerU2MCatchHandlerFrame]] 

Have you seen this behavior before from other customers / installations of IdentityServer?

[brockallen]

Are you using reference tokens?

[sixten]

Yes, we are. So our other systems call the access token verification endpoint, where this seems to be happening, pretty often.

On May 4, 2016, at 17:39, Brock Allen notifications@github.com wrote:

Are you using reference tokens?

— You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub

[brockallen]

Yea, so in short you're hammering IdentityServer (and EF and the DB) with access token validation requests. I'd suggest enabling caching in the UseIdentityServerAccessTokenValidation to lessen the stress on IdentityServer (and EF and the DB).

[sixten]

We aren't using your OWIN middleware on the client side, but we are caching the validation results in a similar way. While that can definitely reduce the load, it can't prevent it, so I'd like to be more confident there isn't a deeper issue at work.

What confuses me about this situation is that, while usage has certainly been ramping up over the time that the service has been live, this problem doesn't crop up only at times of peak load. Nor does it seem like a gradual degradation of service as demand ramps up. The general performance stats on the web server and the database server seem OK, even while this situation exists.

The fact that these thread dumps seem to so consistently show so many threads waiting in RunSync() trying to fetch a Client seems worrisome to me. Do you think I'm misinterpreting the data? Would it be helpful to have access to the thread dump (or to the analysis report)?

[ycadieux]

Having quite the same issue here.

We're running v1.6.2 and using reference tokens. Like sixten, our Idsvr starts throwing connection pool related errors, but our database monitoring shows no signs of any problems.

We are already using the cache mechanism with UseIdentityServerAccessTokenValidation and we still get that behavior from time to time.

Any update with this issue?

[chrisbobo]

We're also having this issue, and under very low load 10 RPS (requests per second). Using version 2.0.0 with reference tokens.

[brockallen]

I know this is an old issue, but I was finally able to repro this issue. I released a quick fix last week to address. Try setting SynchronousReads to true: https://github.com/IdentityServer/IdentityServer3.EntityFramework/blob/master/Source/Core.EntityFramework/EntityFrameworkServiceOptions.cs#L34.

In essence what I think is happening is deadlock between the IO completion ports and the ASP.NET sync context. I'm not 100% sure, but the switch to synchronous calls to the DB works much better.

[brockallen]

I'll open a new issue to track the changes I'll make in a 3.0 release.

[dj90sz]

We're also having the same problems/symptoms but we're using dapper to do async db calls. We've now moved to synchronous db calls now after reading this thread.

@brockallen you might need to recall your memory from almost a year ago, but do you mind explaining how you are able to reproduce this issue? We're trying to reproduce this issue for a week now with no result. Ideally we want to confirm that the changes to synchronous does fix the issue. Thanks!