KeyRingProvider initialization causes thread pool starvation when server starts under load

[amirjalali1]

my application give me frequent

asp.net core 1.1.2 behind load balancer iis arr3

HTTP Error 502.3 - Bad Gateway
The specified CGI application encountered an error and the server terminated the process.

i made a dump file and inspected it using windbg i encountered the following lines. it's like all thread are waiting for keymanagement

could you please take a look at it my app crashes frequently and its a high traffic website
any help would be appreciated

0000001c6f67d5e8 00007ffa506f6c24 [GCFrame: 0000001c6f67d5e8] 
0000001c6f67d838 00007ffa506f6c24 [GCFrame: 0000001c6f67d838] 
0000001c6f67d878 00007ffa506f6c24 [HelperMethodFrame_1OBJ: 0000001c6f67d878] System.Threading.Monitor.ReliableEnterTimeout(System.Object, Int32, Boolean ByRef)
0000001c6f67d9a0 00007ff9bdcbd2fd Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider.GetCurrentKeyRingCore(System.DateTime)
0000001c6f67da50 00007ff9bdcbc5a1 Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Protect(Byte[])
0000001c6f67db10 00007ff9bdcbb839 Microsoft.AspNetCore.Session.CookieProtection.Protect(Microsoft.AspNetCore.DataProtection.IDataProtector, System.String)
0000001c6f67db40 00007ff9bdcb7966 Microsoft.AspNetCore.Session.SessionMiddleware+d__9.MoveNext()
0000001c6f67dbd0 00007ff9bdcb6d45 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Session.SessionMiddleware+d__9, Microsoft.AspNetCore.Session]](d__9 ByRef)
0000001c6f67dc30 00007ff9bdcb6cc9 Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
0000001c6f67dce0 00007ff9bdcb30f9 Microsoft.AspNetCore.Builder.RouterMiddleware+d__4.MoveNext()
0000001c6f67dd40 00007ff9bdcb2a95 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Builder.RouterMiddleware+d__4, Microsoft.AspNetCore.Routing]](d__4 ByRef)
0000001c6f67dda0 00007ff9bdcb2a19 Microsoft.AspNetCore.Builder.RouterMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
0000001c6f67de50 00007ff9bdcb2563 Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware+d__6.MoveNext()
0000001c6f67def0 00007ff9bdcb2105 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware+d__6, Microsoft.AspNetCore.Diagnostics]](d__6 ByRef)
0000001c6f67df50 00007ff9bdcb208f Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
0000001c6f67e010 00007ff9bdcb1b7a Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware+d__3.MoveNext()
0000001c6f67e080 00007ff9bdcb1a25 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware+d__3, Microsoft.AspNetCore.Diagnostics]](d__3 ByRef)
0000001c6f67e0e0 00007ff9bdcb19a9 Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
0000001c6f67e190 00007ff9bdcb0b35 Microsoft.AspNetCore.Server.IISIntegration.IISMiddleware+d__8.MoveNext()
0000001c6f67e280 00007ff9bdcafec5 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Server.IISIntegration.IISMiddleware+d__8, Microsoft.AspNetCore.Server.IISIntegration]](d__8 ByRef)
0000001c6f67e2e0 00007ff9bdcafe49 Microsoft.AspNetCore.Server.IISIntegration.IISMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
0000001c6f67e390 00007ff9bdca9ed5 Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware+d__3.MoveNext()
0000001c6f67e3e0 00007ff9bdca9c35 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware+d__3, Microsoft.AspNetCore.Hosting]](d__3 ByRef)
0000001c6f67e440 00007ff9bdca9bb9 Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
0000001c6f67e4f0 00007ff9bdca9b12 Microsoft.AspNetCore.Hosting.Internal.HostingApplication.ProcessRequestAsync(Context)
0000001c6f67e520 00007ff9bdc8e13e Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Frame`1+d__2[[Microsoft.AspNetCore.Hosting.Internal.HostingApplication+Context, Microsoft.AspNetCore.Hosting]].MoveNext()
0000001c6f67e620 00007ff9bdc87275 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Frame`1+d__2[[Microsoft.AspNetCore.Hosting.Internal.HostingApplication+Context, Microsoft.AspNetCore.Hosting]], Microsoft.AspNetCore.Server.Kestrel]](d__2 ByRef)
0000001c6f67e680 00007ff9bdc8719d Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Frame`1[[Microsoft.AspNetCore.Hosting.Internal.HostingApplication+Context, Microsoft.AspNetCore.Hosting]].RequestProcessingAsync()
0000001c6f67e770 00007ffa191676b5 System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].InnerInvoke()
0000001c6f67e7c0 00007ffa19135a26 System.Threading.Tasks.Task.Execute()
0000001c6f67e800 00007ffa190d16ee System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
0000001c6f67e870 00007ffa19135f93 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)
0000001c6f67e920 00007ffa19135d2f System.Threading.Tasks.Task.ExecuteEntry(Boolean)
0000001c6f67e960 00007ffa191966bc System.Threading.ThreadPoolWorkQueue.Dispatch()

@blowdart @natemcmaster @shanselman
it may be related to #228
the way i initialized redis at startup is :

{
        var redis = RedisConnectionManager.SafeCoonect;
    
            
                services
            .AddDataProtection()
            .SetApplicationName("xxxxxx")
          .PersistKeysToRedis(redis, "xxxzzzz"

            return services.AddSession(options =>
            {
                options.IdleTimeout = TimeSpan.FromHours(12);
                options.CookieName = "m";
            });
}

and safeconnect is

        private static Lazy<ConfigurationOptions> configOptions
            = new Lazy<ConfigurationOptions>(() =>
            {
                var configOptions = new ConfigurationOptions();

                configOptions.EndPoints.Add("xxx.xxx.xxx.xxxx:6379");
                configOptions.SyncTimeout = 4000;
                configOptions.AbortOnConnectFail = false;
                return configOptions;
            });

 
        private static readonly Lazy<ConnectionMultiplexer> LazyConnection = new Lazy<ConnectionMultiplexer>(() =>
        {
            var connection = ConnectionMultiplexer.Connect(configOptions.Value);
            connection.PreserveAsyncOrder = false;
            return connection;
 
        });

        public static ConnectionMultiplexer SafeCoonect
        {
            get
            {
                return LazyConnection.Value;
            }
        }

[blowdart]

Is your redis instance restarting at all?

[amirjalali1]

no it hasn't restarted at all

[amirjalali1]

after digging more on dump file
!SyncBlk

78 00000262c8a9d2e8 42711 1 00000262cc5cf810 151e84090 00000262ae270438 System.Object

and !clrstack

000000758e8fcbd8 00007ffa506f6c24 [GCFrame: 000000758e8fcbd8] 
000000758e8fcca8 00007ffa506f6c24 [HelperMethodFrame_1OBJ: 000000758e8fcca8] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
000000758e8fcdd0 00007ff9bdcb6d9a StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[[System.__Canon, System.Private.CoreLib]](StackExchange.Redis.Message, StackExchange.Redis.ResultProcessor`1, StackExchange.Redis.ServerEndPoint)
000000758e8fcf70 00007ff9bdcb663a StackExchange.Redis.RedisBase.ExecuteSync[[System.__Canon, System.Private.CoreLib]](StackExchange.Redis.Message, StackExchange.Redis.ResultProcessor`1, StackExchange.Redis.ServerEndPoint)
000000758e8fd028 00007ffa1ccbd64e [StubHelperFrame: 000000758e8fd028] 
000000758e8fd080 00007ff9bdcb657b StackExchange.Redis.RedisDatabase.ListRange(StackExchange.Redis.RedisKey, Int64, Int64, StackExchange.Redis.CommandFlags)
000000758e8fd120 00007ff9bdcb4a7a Microsoft.AspNetCore.DataProtection.RedisXmlRepository+d__4.MoveNext()
000000758e8fd180 00007ffa190bb3b4 System.Collections.Generic.List`1[[System.__Canon, System.Private.CoreLib]]..ctor(System.Collections.Generic.IEnumerable`1)
000000758e8fd1f0 00007ffa3a6227d5 System.Linq.Enumerable.ToList[[System.__Canon, System.Private.CoreLib]](System.Collections.Generic.IEnumerable`1)
000000758e8fd240 00007ff9bdcb477f Microsoft.AspNetCore.DataProtection.RedisXmlRepository.GetAllElements()
000000758e8fd280 00007ff9bdcb3dad Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager.GetAllKeys()
000000758e8fd4d0 00007ff9bdcb1378 Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider.CreateCacheableKeyRingCore(System.DateTimeOffset, Microsoft.AspNetCore.DataProtection.KeyManagement.IKey)
000000758e8fd5d0 00007ff9bdcb12fc Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider.Microsoft.AspNetCore.DataProtection.KeyManagement.Internal.ICacheableKeyRingProvider.GetCacheableKeyRing(System.DateTimeOffset)
000000758e8fd600 00007ff9bdcb1137 Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider.GetCurrentKeyRingCore(System.DateTime)
000000758e8fd6b0 00007ff9bdcb0641 Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Protect(Byte[])
000000758e8fd770 00007ff9bdcaea19 Microsoft.AspNetCore.Session.CookieProtection.Protect(Microsoft.AspNetCore.DataProtection.IDataProtector, System.String)
000000758e8fd7a0 00007ff9bdca9386 Microsoft.AspNetCore.Session.SessionMiddleware+d__9.MoveNext()
000000758e8fd830 00007ff9bdca64c5 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Session.SessionMiddleware+d__9, Microsoft.AspNetCore.Session]](d__9 ByRef)
000000758e8fd890 00007ff9bdca6349 Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
000000758e8fd940 00007ff9bdca2bf9 Microsoft.AspNetCore.Builder.RouterMiddleware+d__4.MoveNext()
000000758e8fd9a0 00007ff9bdca2995 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Builder.RouterMiddleware+d__4, Microsoft.AspNetCore.Routing]](d__4 ByRef)
000000758e8fda00 00007ff9bdca2919 Microsoft.AspNetCore.Builder.RouterMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
000000758e8fdab0 00007ff9bdca2116 Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware+d__6.MoveNext()
000000758e8fdb50 00007ff9bdca1c05 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware+d__6, Microsoft.AspNetCore.Diagnostics]](d__6 ByRef)
000000758e8fdbb0 00007ff9bdca1b8f Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
000000758e8fdc70 00007ff9bdca167a Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware+d__3.MoveNext()
000000758e8fdce0 00007ff9bdca1525 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware+d__3, Microsoft.AspNetCore.Diagnostics]](d__3 ByRef)
000000758e8fdd40 00007ff9bdca14a9 Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
000000758e8fddf0 00007ff9bdca05d5 Microsoft.AspNetCore.Server.IISIntegration.IISMiddleware+d__8.MoveNext()
000000758e8fdee0 00007ff9bdc9fd75 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Server.IISIntegration.IISMiddleware+d__8, Microsoft.AspNetCore.Server.IISIntegration]](d__8 ByRef)
000000758e8fdf40 00007ff9bdc9fcf9 Microsoft.AspNetCore.Server.IISIntegration.IISMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
000000758e8fdff0 00007ff9bdc97685 Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware+d__3.MoveNext()
000000758e8fe040 00007ff9bdc973e5 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware+d__3, Microsoft.AspNetCore.Hosting]](d__3 ByRef)
000000758e8fe0a0 00007ff9bdc97369 Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.Invoke(Microsoft.AspNetCore.Http.HttpContext)
000000758e8fe150 00007ff9bdc972c2 Microsoft.AspNetCore.Hosting.Internal.HostingApplication.ProcessRequestAsync(Context)
000000758e8fe180 00007ff9bdc88b1e Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Frame`1+d__2[[Microsoft.AspNetCore.Hosting.Internal.HostingApplication+Context, Microsoft.AspNetCore.Hosting]].MoveNext()
000000758e8fe280 00007ff9bdc86bb5 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Frame`1+d__2[[Microsoft.AspNetCore.Hosting.Internal.HostingApplication+Context, Microsoft.AspNetCore.Hosting]], Microsoft.AspNetCore.Server.Kestrel]](d__2 ByRef)
000000758e8fe2e0 00007ff9bdc8670d Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Frame`1[[Microsoft.AspNetCore.Hosting.Internal.HostingApplication+Context, Microsoft.AspNetCore.Hosting]].RequestProcessingAsync()
000000758e8fe3d0 00007ffa191676b5 System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].InnerInvoke()
000000758e8fe420 00007ffa19135a26 System.Threading.Tasks.Task.Execute()
000000758e8fe460 00007ffa190d16ee System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000758e8fe4d0 00007ffa19135f93 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)
000000758e8fe580 00007ffa19135d2f System.Threading.Tasks.Task.ExecuteEntry(Boolean)
000000758e8fe5c0 00007ffa191966bc System.Threading.ThreadPoolWorkQueue.Dispatch()
000000758e8fea98 00007ffa1ccbcb13 [DebuggerU2MCatchHandlerFrame: 000000758e8fea98] 

[amirjalali1]

what should i do ? can i go for unc? should i change appname for migrating to unc? what other options do i have?

[blowdart]

So it looks like the redis connection is failing somehow. Is there anything in the redis logs to indicate failed connections at that time?

[amirjalali1]

redis log level is set to notice and i couldn't find any evidence of failed connection.
where should i look for failed connections?
i checked info on redis-cli and slowlog and redig log file but there wasn't anything suspicious.

[natemcmaster]

it's like all thread are waiting for keymanagement

FYI the key ring is a singleton, so this is expected behavior. Only one thread should load the key ring, and all other threads wait. The second stack you posted is the thread attempting to create the key ring, and it appears to be hung on communication with Redis.

The Redis layer is actually pretty light (see RedisXmlRepository). To help isolate the issue, can you make sure the following code executes successfully?

var database = RedisConnectionManager.SafeCoonect.CreateDatabase();
var keys =  new List<XElement>();
RedisKey key = "xxxzzzz";
foreach (var value in database.ListRange(key))
{
    keys.Add(XElement.Parse(value));
}

[amirjalali1]

@natemcmaster @blowdart
i made some changes to above code CreateDatabase was not available on connection multiplexer so i change it to GetDatabase and run it on an mvc app

             string keystrings="";
            Stopwatch stopwatch = new Stopwatch();
        var database = RedisConnectionManager.SafeCoonect.GetDatabase();
                var keys = new List<XElement>();
                RedisKey key = "xxxzzzz";
                foreach (var value in database.ListRange(key))
                {
                    keys.Add(XElement.Parse(value));
                }
                foreach (var k in keys)
                {
                    keystrings = k.Name.ToString() + ": " + k.Value.ToString() + Environment.NewLine;
                }
           stopwatch.Stop();

code execution time :

00:00:00.0350811

and it ran successfully. i don't know maybe load balancing and high traffic causes this problem.
does switching to unc makes it better it terms of not requiring to get connected and disconnected?

[michaelpaulus]

We also had this issue, in Azure App Services. It is writing to the shared filesystem. We also tried the Blob storage provider without any luck. We were running out of threads while the lock happened inside of GetCurrentKeyRingCore when apps randomly restarted under heavy load.

n2y.Web.Websites.Login_7180_CrashHangAnalysis.mht.zip

The only workaround we could find is to encrypt something during the Config method of the startup:

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
   ....
    var instance = ActivatorUtilities.CreateInstance<StartupDataProtection>(app.ApplicationServices);
    instance.Init();
}

public class StartupDataProtection
 {
     IDataProtector _protector;

     // the 'provider' parameter is provided by DI
     public StartupDataProtection(IDataProtectionProvider provider)
     {
         _protector = provider.CreateProtector(typeof(StartupDataProtection).FullName);
     }

     public void Init()
     {
         var value = nameof(StartupDataProtection);
         // protect the payload
         string protectedPayload = _protector.Protect(value);
         // unprotect the payload
         string unprotectedPayload = _protector.Unprotect(protectedPayload);
     }
 }

[natemcmaster]

This looks like thread pool starvation.

KeyRingProvider requires initialization, performed only once by the GetCurrentKeyRingCore method. This is a critical section, protected by a thread monitor so that only one thread can enter. This is what I see on the stack traces you've shared: many threads are waiting for this critical section and one thread in the critical section.

The initialization in KeyRingProvider.GetCurrentKeyRingCore will call on RedisXmlRepository or AzureBlobXmlRepository to fetch keys. This fetching process run some async operations....which means they call to the thread pool for resources. If too many threads are blocked waiting for KeyRingProvider.GetCurrentKeyRingCore, then RedisXmlRepository or AzureBlobXmlRepository can't get a thread to complete their work.

@michaelpaulus's workaround is simple and effective. It moves KeyRingProvider's initialization into hosting startup, which happens before the app begins accepting and processing requests. Because there is no load yet, there are plenty of threads and initialization completes successfully.

To triage team: possible solutions:

• make it easier to run KeyRingProvider initialization during hosting startup. Could be opt-in.
• make that default (requires new API in hosting so we can plug dataprotection into startup) cc @JunTaoLuo @davidfowl
• (maybe) ensure key repositories like RedisXmlRepository complete on the same thread. This may not be easy given that we use networking libraries we don't own, and I don't know if they will provide sync operations.

[michaelpaulus]

@natemcmaster just wanted to add my opinion as a consumer, it would be great if this was automatic, not opt-in since you have to realize this would be an issue in the first place to know to opt-in. It only happens when initializing during heavy load and is very hard to detect until production. We did many load tests on our site before hitting production, it was even working really well for a full day under production until one of the instances restarted for some reason during heavy load, then it was all over. A single instance was throwing 500 errors. This also happened with the default provider that writes the keys to the file system (FYI, not just Blob and Redis).

Thanks!

[amirjalali1]

@michaelpaulus
What is unprotectedPayload ? and how should i use it? code you please provide a working sample?

[amirjalali1]

@michaelpaulus
should i register IDataProtectionProvider at startup?

[michaelpaulus]

@1amirjalai you don't need to do anything more than you are probably already doing to register the IDataProtectionProvider at startup, services.AddDataProtection().

The unprotectedPayload is not needed for anything, what the code is doing is just encrypting / decrypting a string on startup so that as @natemcmaster described, it forces the loading of the keys before any load hits the server. This prevents the many 500 errors that you and I were seeing.