IIS AspNetCore Module V2 throws failed to load coreclr

[akiander]

We upgraded our asp.net core site from .NET Core 2.2 --> 3.1

The site works fine for about 18 hours and then crashes. Restarting it gives us:

HTTP Error 500.37 - ANCM Failed to Start Within Startup Time Limit

Looking in the event log, we see this:

3/4/2020 2:31:54 AM
Source: WAS
EventId: 5009
A process serving application pool 'SSO' terminated unexpectedly. The process id was '11960'. The process exit code was '0xc0000409'.

3/4/2020 2:33:51 AM
Source: WAS
EventId: 5010
A process serving application pool 'SSO' failed to respond to a ping. The process id was '13988'.

3/4/2020 2:35:52 AM
EventId: 1007
Source: IIS AspNetCore Module V2
Application '/LM/W3SVC/28/ROOT' with physical root 'D:\Sites\SSO\Site-Prod\' failed to load coreclr. Exception message:
Managed server didn't initialize after 120000 ms.

No amount of recycling / rebooting or redeploying gets the site back up and running.

Deploying the old 2.2 code works immediately.

Any idea what might be causing this?

[analogrelay]

Generally this occurs because either: Your application is taking longer than 120 seconds to start up and be able to process the first request, or your application is crashing. Can you post a runnable sample that reproduces the problem or detail exactly what your startup processes are doing (Program.Main, Startup.Configure, etc.). If something there is taking longer than 120 seconds, this is expected. (You can configure the startup timeout if you actually need to take longer than 120 seconds)

We have more detailed troubleshooting docs for IIS hosting here: https://docs.microsoft.com/en-us/aspnet/core/test/troubleshoot-azure-iis?view=aspnetcore-3.1

[akiander]

I used Serilog and try/catch structures to instrument the application to find what portion was crashing or causing us to take longer than 120 seconds but all of the logs showed that nothing was slow or crashing.

We went through the Program.cs and Startup.cs to make sure they match the current dotnet new templates for aspnetcore 3.1 applications so I don't think that is our issue. Besides, our environment has two web servers and this code works fine on one of them but not the other.

I finally "fixed" this by adding this to the .csproj file:

  <PropertyGroup>
    <AspNetCoreHostingModel>OutOfProcess</AspNetCoreHostingModel>
  </PropertyGroup>

So with this being the only change I made, now the web application appears to startup and run normally on this server.

What's even more strange is that we have two other virtual directories running on the same web server running beta versions of the same code and both work using in-process hosting without an issue.

Even though it's back to functional, any ideas on the root cause as to why it cannot run in-process but the same code runs fine with out-of-process hosting?

[analogrelay]

Are you calling WebHost.CreateDefaultBuilder in your Program.cs to build your web host or have you changed that code manually? One thing that causes this problem is if you don't call .UseIIS on your IWebHostBuilder instance. That is done automatically when you use WebHost.CreateDefaultBuilder but if you've changed that and are building your code up manually you need to explicitly call it to enable the managed components that plug in to IIS.

If you're unsure, you can share your Program.cs and Startup.cs (if you need to trim out confidential information that should be OK). Even better would be if you can provide a runnable sample application.

[akiander]

Yes, we call Microsoft.Extensions.Hosting.Host.CreateDefaultBuilder(args)

Here's the full code for Program.cs

using System;
using Microsoft.ApplicationInsights.Extensibility;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.ApplicationInsights;
using Serilog;
using Serilog.Events;
using Serilog.Sinks.SystemConsole.Themes;
using Sso.Host.Logging;

namespace Sso.Host {

    public class Program {

        public static int Main(string[] args) {

            // Temporary logging in order to diagnose startup issues experienced after the move to .NET Core 3.1
            var logDirectory = "serverlogs.txt";
            Log.Logger = new LoggerConfiguration()
                .MinimumLevel.Debug()
                .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
                .MinimumLevel.Override("System", LogEventLevel.Warning)
                .MinimumLevel.Override("Microsoft.AspNetCore.Authentication", LogEventLevel.Information)
                .Enrich.FromLogContext()
                .WriteTo.File(logDirectory,
                    fileSizeLimitBytes: 1_000_000,
                    rollOnFileSizeLimit: true,
                    shared: true,
                    flushToDiskInterval: TimeSpan.FromSeconds(1))
                .WriteTo.Console(outputTemplate: "[{Timestamp:HH:mm:ss} {Level}] {SourceContext}{NewLine}{Message:lj}{NewLine}{Exception}{NewLine}", theme: AnsiConsoleTheme.Literate)
                .CreateLogger();

            try {
                Log.Information("Sso.Host.Program.Main - Starting host...");
                CreateHostBuilder(args).Build().Run();
                return 0;
            } catch (Exception ex) {
                Log.Fatal(ex, "Sso.Host.Program.Main - Host terminated unexpectedly.");
                return 1;
            } finally {
                Log.CloseAndFlush();
            }
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Microsoft.Extensions.Hosting.Host.CreateDefaultBuilder(args)
                .ConfigureWebHostDefaults(webBuilder => {
                    webBuilder.UseStartup<Sso.Host.Startup>();
                    webBuilder.ConfigureLogging((hostingContext, logging) => {

                        logging.AddSerilog(Log.Logger);

                        logging.AddConfiguration(hostingContext.Configuration.GetSection("Logging"));

                        if ((hostingContext?.HostingEnvironment?.EnvironmentName?.Contains("dev", StringComparison.InvariantCultureIgnoreCase) ?? false)
                        || (hostingContext?.HostingEnvironment?.EnvironmentName?.Contains("local", StringComparison.InvariantCultureIgnoreCase) ?? false)) {
                            logging.AddConsole();
                            logging.AddDebug();
                        }

                        logging.AddApplicationInsights(hostingContext.Configuration["ApplicationInsights:InstrumentationKey"]);
                        logging.Services.AddTransient<ITelemetryInitializer, SsoTelemetryInitializer>();

                        // Application Insights LogLevel settings
                        var logLevelConfig = hostingContext.Configuration.GetSection("Logging:LogLevel");
                        foreach (var item in logLevelConfig.GetChildren()) {
                            var key = item.Key.Contains("default", StringComparison.InvariantCultureIgnoreCase) ? "" : item.Key;
                            var logLevel = Enum.Parse<LogLevel>(item.Value, true);
                            logging.AddFilter<ApplicationInsightsLoggerProvider>(key, logLevel);
                        }

                    });
                });
                
    }
}

And here's the full code for Startup.cs

using System;
using System.Collections.Generic;
using System.IdentityModel.Tokens.Jwt;
using System.IO;
using System.Linq;
using System.Reflection;
using System.Text.Encodings.Web;
using System.Threading.Tasks;
using CV.Common.Sources.Salesforce;
using CV.Common.Sources.Salesforce.Sso;
using IdentityServer4;
using IdentityServer4.AccessTokenValidation;
using IdentityServer4.EntityFramework.DbContexts;
using IdentityServer4.Services;
using Microsoft.ApplicationInsights.Extensibility;
using Microsoft.AspNetCore.Authentication;
using Microsoft.AspNetCore.Authorization;
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.DataProtection;
using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Rewrite;
using Microsoft.EntityFrameworkCore;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using Sso.Host.Authorization;
using Sso.Host.Extensions;
using Sso.Host.Filters;
using Sso.Host.Logging;
using Sso.Host.Managers;
using SsoExtensions;
using SsoExtensions.DataProtection;
using SsoExtensions.UserStorage;

namespace Sso.Host {

    public class Startup {

        public Startup(IHostEnvironment env) {
            var builder = new ConfigurationBuilder()
                .SetBasePath(Directory.GetCurrentDirectory())
                .AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)
                .AddJsonFile($"appsettings.{env.EnvironmentName}.json", optional: true, reloadOnChange: true)
                .AddEnvironmentVariables();

            Configuration = builder.Build();
        }

        public static IConfigurationRoot Configuration { get; set; }

        // This method gets called by the runtime. Use this method to add services to the container.
        public void ConfigureServices(IServiceCollection services) {
            JwtSecurityTokenHandler.DefaultInboundClaimTypeMap.Clear();
            //IMPORTANT - Do not omit this claim mapping or claims may not have the correct names
            JwtSecurityTokenHandler.DefaultInboundClaimTypeMap = new Dictionary<string, string>();

            // Add application services.
            services.AddSingleton<IConfigurationRoot>(provider => Configuration);
            services.AddApplicationInsightsTelemetry(Configuration);
            services.AddTransient<ITelemetryInitializer, SsoTelemetryInitializer>();
            services.AddCors();

            services.ConfigureNonBreakingSameSiteCookies();

            var ssoConnection = Configuration.GetConnectionString("SsoConnection");

            services.AddHealthChecks()
               .AddSqlServer(
                    connectionString: ssoConnection,
                    healthQuery: "SELECT 1;",
                    name: "sql",
                    failureStatus: Microsoft.Extensions.Diagnostics.HealthChecks.HealthStatus.Unhealthy,
                    tags: new string[] { "db", "sql", "sqlserver" });

            var migrationsAssembly = typeof(Startup).GetTypeInfo().Assembly.GetName().Name;
            services.AddDbContext<SsoStorageContext>(builder => {
                builder.UseSqlServer(ssoConnection, sqlOptions => {
                    sqlOptions.MigrationsAssembly(migrationsAssembly);
                    sqlOptions = sqlOptions.EnableRetryOnFailure();
                });

            }, ServiceLifetime.Scoped);

            services.AddDataProtection()
                .PersistKeysToFileSystem(new DirectoryInfo(Configuration["DataProtectionKeyLocation"]));

            var dataProtectionManagerOptions = new DataProtectionManagerOptions() {
                Name = "DataProtectionManager",
                TokenLifespan = TimeSpan.FromDays(1)
            };
            services.AddScoped<IDataProtectionManagerOptions, DataProtectionManagerOptions>();
            services.AddScoped<IDataProtectionManager, DataProtectionManager>();

            services
                .AddFluentEmail(Configuration["EmailConfiguration:defaultSenderEmail"], $"No-Reply")
                .AddRazorRenderer()
                .AddSmtpSender(Configuration["EmailConfiguration:SmtpServer"], int.Parse(Configuration["EmailConfiguration:SmtpPort"]));

            services.AddMvc(options => {
                options.Filters.Add(typeof(CustomExceptionFilterAttribute));
                options.EnableEndpointRouting = false;
            });

            services.AddIdentityServer(options => {
                    options.Events.RaiseErrorEvents = true;
                    options.Events.RaiseFailureEvents = true;
                    options.Events.RaiseInformationEvents = true;
                    options.Events.RaiseSuccessEvents = true;
                })
                .AddSigningCredential(Certificate.Get(Configuration["SigningCredentialsCertificateName"]))
                .AddInMemoryIdentityResources(IdentityResourceSettings.Get())
                .AddInMemoryApiResources(ApiResourceSettings.Get())
                .AddInMemoryClients(Clients.Get(Configuration))
                .AddOperationalStore(options => {
                    options.ConfigureDbContext = builder =>
                        builder.UseSqlServer(ssoConnection,
                            sqlOptions => {
                                sqlOptions.MigrationsAssembly(migrationsAssembly);
                                sqlOptions.EnableRetryOnFailure();
                            });
                    options.EnableTokenCleanup = true;
                    options.TokenCleanupInterval = 30;
                })
                .AddCustomUserStore();

            var clientId = Configuration["AzureAD:ClientId"];
            var authority = $"{Configuration["AzureAd:AadInstance"]}{Configuration["AzureAd:Tenant"]}";
            var signedOutRedirectUri = Configuration["AzureAd:PostLogoutRedirectUri"];

            
            var integrationCtx = new IntegrationContext(Configuration["IntegrationConnection"]);
            var environment = Configuration["Environment"] == "prod" ? "production" : "staging-main";
            var salesforceSettings = integrationCtx.SalesforceOAuthSettings.FirstOrDefault(s => s.Environment == environment && s.App == "sso");
            var useSalesforce = Configuration["UseSalesforceIdentityProvider"] == "true";
            var salesForceDisplayName = useSalesforce ? "Partners" : "";
            var salesforceApiSettings = integrationCtx.SalesforceApiSettings.FirstOrDefault(s => s.Environment == environment);
            services.AddSingleton<SsoClient>((provider) => {
                var svcProvider = services.BuildServiceProvider(); 
                var factory = svcProvider.GetService<ILoggerFactory>();
                var logger = factory.CreateLogger<SsoClient>(); 
                return new SsoClient(salesforceApiSettings.RestBaseUrl,
                    salesforceApiSettings.Username,
                    salesforceApiSettings.Password,
                    salesforceApiSettings.ApiKey,
                    salesforceApiSettings.ClientSecret,
                    salesforceApiSettings.ClientId,
                    logger);
            });

            services.AddAuthentication()
                .AddCookie(options => {
                    options.Cookie.SameSite = SameSiteMode.None;
                })
                .AddSalesforce(Constants.Provider_Salesforce, salesForceDisplayName, options => {
                    options.ClientId = salesforceSettings.ClientId;
                    options.ClientSecret = salesforceSettings.ClientSecret;
                    options.AuthorizationEndpoint = salesforceSettings.AuthorizationEndpoint;
                    options.TokenEndpoint = salesforceSettings.TokenEndpoint;
                    options.CallbackPath = new PathString("/signin-salesforce");
                    options.SignInScheme = IdentityServerConstants.ExternalCookieAuthenticationScheme;
                    options.ClaimActions.MapJsonKey("sub", Constants.ClaimType_SalesforceUserId);
                    options.ClaimActions.MapJsonKey("email", Constants.ClaimType_Email);
                    options.ClaimActions.MapJsonKey("name", Constants.ClaimType_SalesforceName);
                    options.ClaimActions.MapJsonKey("given_name", Constants.ClaimType_SalesforceGivenName);
                    options.ClaimActions.MapJsonKey("family_name", Constants.ClaimType_SalesforceFamilyName);
                })
                .AddOpenIdConnect(Constants.Provider_AzureActiveDirectory, "Employee Login", options => {

                    options.SignInScheme = IdentityServerConstants.ExternalCookieAuthenticationScheme;
                    options.ClientId = clientId;
                    options.Authority = authority;
                    options.SignedOutRedirectUri = signedOutRedirectUri;
                    options.GetClaimsFromUserInfoEndpoint = true;
                    options.Events = new Microsoft.AspNetCore.Authentication.OpenIdConnect.OpenIdConnectEvents() {
                        OnRedirectToIdentityProvider = n => {
                            if ("true".Equals(n.HttpContext.Items["promptnone"])) {
                                n.ProtocolMessage.Prompt = "none";
                            }
                            return Task.CompletedTask;
                        },
                        OnMessageReceived = async m => {
                            try {
                                if (!string.IsNullOrWhiteSpace(m.ProtocolMessage.Error)) {

                                    switch (m.ProtocolMessage.Error) {
                                        //https://openid.net/specs/openid-connect-core-1_0.html#AuthError
                                        case "interaction_required":
                                        case "login_required":
                                        case "account_selection_required":
                                        case "consent_required":
                                        case "invalid_request_uri":
                                        case "invalid_request_object":
                                        case "request_not_supported":
                                        case "request_uri_not_supported":
                                        case "registration_not_supported":
                                            var url = m.Properties.Items["returnUrl"];
                                            var encoded = UrlEncoder.Default.Encode(url);

                                            var sp = services.BuildServiceProvider();
                                            var interactSvc = sp.GetService<IIdentityServerInteractionService>();
                                            var context = await interactSvc.GetAuthorizationContextAsync(url);

                                            if (context != null) {

                                                var state = ProtocolManager.ExtractStateFromUrl(url);
                                                var redirectUri = context.RedirectUri;

                                                //the hash fragment assumes a javascript client which should be okay 
                                                //since this scenario is most commonly used for iFrames via javascript 
                                                m.HttpContext.Response.Redirect($"{redirectUri}#error={m.ProtocolMessage.Error}&state={state}");
                                                m.HandleResponse();
                                            }
                                            break;

                                        default: {
                                                var provider = services.BuildServiceProvider();
                                                var factory = provider.GetService<ILoggerFactory>();
                                                var logger = factory.CreateLogger<Startup>();
                                                logger?.LogError($"Unrecognized Protocol Error: {m.ProtocolMessage.Error}");
                                                break;
                                            }

                                    }
                                }
                            }
                            catch (Exception exc) {
                                var provider = services.BuildServiceProvider();
                                var factory = provider.GetService<ILoggerFactory>();
                                var logger = factory.CreateLogger<Startup>();
                                logger?.LogError($"Azure AD Protocol Error: {exc.ToString()}");
                            }
                        }
                    };
                })
                .AddIdentityServerAuthentication("REDACTED", options => {
                    options.ApiSecret = "REDACTED";
                    options.Authority = Configuration["SsoBaseUrl"]; 
                    options.ApiName = "REDACTED";
                    options.EnableCaching = true;
                    options.CacheDuration = TimeSpan.FromMinutes(5);
                    options.SupportedTokens = SupportedTokens.Reference;
                });

            services.AddAuthorization(options => {
                var allowedSubjects = Configuration["PrivilegedApiAllowedSubjects"].Split(',').ToList();
                options.AddPolicy("PrivilegedApi", policy =>
                policy.Requirements.Add(new PrivilegedApiRequirement(allowedSubjects)));
            });

            services.AddSingleton<IAuthorizationHandler, PrivilegedApiHandler>();

        }

        // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
        public void Configure(IApplicationBuilder app, IHostEnvironment env) {

            app.UseCookiePolicy(); // Add this before any other middleware that might write cookies

            // add the endpoint to view health checks
            app.UseHealthChecks("/health", new Microsoft.AspNetCore.Diagnostics.HealthChecks.HealthCheckOptions {
                Predicate = _ => true,
                ResponseWriter = HealthChecks.UI.Client.UIResponseWriter.WriteHealthCheckUIResponse
            });

            var rewriteOptions = new RewriteOptions();
            rewriteOptions.AddRewrite("(^core/)(.*)", "$2", true);
            rewriteOptions.AddRedirectToHttps();
            app.UseRewriter(rewriteOptions);

            InitializeDatabase(app);

            if (env.IsDevelopment()) {
                app.UseDeveloperExceptionPage();
                app.UseBrowserLink();
                app.UseDatabaseErrorPage();
            }
            else {
                app.UseExceptionHandler("/Home/Error");
            }

            app.UseStaticFiles();

            app.UseIdentityServer();

            app.UseMvc(routes => {
                routes.MapRoute(
                    name: "default",
                    template: "{controller=Home}/{action=Index}/{id?}");
            });

        }

        private void InitializeDatabase(IApplicationBuilder app) {

            using (var serviceScope = app.ApplicationServices.GetService<IServiceScopeFactory>().CreateScope()) {
                // background: http://docs.identityserver.io/en/latest/quickstarts/5_entityframework.html
                serviceScope.ServiceProvider.GetRequiredService<PersistedGrantDbContext>().Database.Migrate();
            }

            using (var serviceScope = app.ApplicationServices.GetService<IServiceScopeFactory>().CreateScope()) {
                serviceScope.ServiceProvider.GetRequiredService<SsoStorageContext>().Database.Migrate();
            }

            using (var serviceScope = app.ApplicationServices.GetService<IServiceScopeFactory>().CreateScope()) {
               serviceScope.ServiceProvider.GetRequiredService<SsoTestUserStore>().Cleanup();
            }

        }

    }

}

[analogrelay]

How long does that InitializeDatabase call in Startup.Configure tend to take? You mentioned you instrumented the code to collect timings, did you include this? The entire body of ConfigureServices and Configure (plus additional framework startup code) must complete within that startup timeout I mentioned earlier (120 seconds) or ANCM will consider the app to have failed to start. If the total duration of those processes is taking longer than 120 seconds then you may want to increase the timeout (the “startupTimeLimit” option configured in web.config as described here: https://docs.microsoft.com/en-us/aspnet/core/host-and-deploy/aspnet-core-module?view=aspnetcore-3.1#attributes-of-the-aspnetcore-element)

[akiander]

yes I instrumented the code by just spreading out Serilog statements throughout the startup logic. I took that out when I determined that this code would not take longer than 120 seconds. I just pulled that branch and reran it and the total startup time is about 10 seconds

2020-03-10 11:00:57.299 -04:00 [INF] Sso.Host.Program.Main - Starting host...
2020-03-10 11:01:02.148 -04:00 [INF] Sso.Host.Startup.ConfigureServices - 1
2020-03-10 11:01:02.155 -04:00 [INF] Sso.Host.Startup.ConfigureServices - 2
2020-03-10 11:01:02.182 -04:00 [INF] Sso.Host.Startup.ConfigureServices - 3
2020-03-10 11:01:02.254 -04:00 [INF] Sso.Host.Startup.ConfigureServices - 4
2020-03-10 11:01:02.396 -04:00 [INF] Sso.Host.Startup.ConfigureServices - 5
2020-03-10 11:01:02.996 -04:00 [INF] Sso.Host.Startup.ConfigureServices - 6
2020-03-10 11:01:03.937 -04:00 [INF] Sso.Host.Startup.ConfigureServices - 7
2020-03-10 11:01:06.894 -04:00 [INF] Sso.Host.Startup.ConfigureServices - 8
2020-03-10 11:01:06.946 -04:00 [INF] Sso.Host.Startup.ConfigureServices - 9
2020-03-10 11:01:08.496 -04:00 [INF] Sso.Host.Startup.Configure - a
2020-03-10 11:01:08.507 -04:00 [INF] Sso.Host.Startup.Configure - b
2020-03-10 11:01:08.508 -04:00 [INF] Sso.Host.Startup.Configure - c
2020-03-10 11:01:08.510 -04:00 [INF] Sso.Host.Startup.InitializeDatabase - a
2020-03-10 11:01:09.624 -04:00 [INF] Sso.Host.Startup.InitializeDatabase - b
2020-03-10 11:01:10.098 -04:00 [INF] Sso.Host.Startup.InitializeDatabase - c
2020-03-10 11:01:10.258 -04:00 [INF] Sso.Host.Startup.InitializeDatabase - d
2020-03-10 11:01:10.259 -04:00 [INF] Sso.Host.Startup.Configure - d
2020-03-10 11:01:10.261 -04:00 [INF] Sso.Host.Startup.Configure - e
2020-03-10 11:01:10.330 -04:00 [INF] Sso.Host.Startup.Configure - f
2020-03-10 11:01:10.479 -04:00 [INF] Sso.Host.Startup.Configure - g

This code works fine when running out of process but when the only thing I change is to run in-process, then it always throws HTTP Error 500.37 - ANCM Failed to Start Within Startup Time Limit

[analogrelay]

Have you tried increasing the startup time limit anyway (as a way of exploring the possibilities)?

Is there any way you could provide a runnable sample that reproduces the problem? It's very difficult to see where the delay could be coming from without full context. Let me know if you're able to share something but want to keep it confidential.

[sunnylnct007]

I was using the default .net core 3.1 web template with Blazor and got the same error in azure app service hosting.
The startup
is Host.CreateDefaultBuilder(args)
.ConfigureWebHostDefaults(webBuilder =>
{
webBuilder.UseStartup();
});

Below solved by

OutOfProcess

as suggested by @akiander but is this a bug?

[analogrelay]

@sunnylnct007 this error message can have a lot of different causes. Unless your app is the same one as @akiander, I'd suggest filing a new bug instead and providing as much detail as you can (errors from the Windows Event Log, etc.). If they end up having the same root cause, we can figure that out later :).

[akiander]

I'll work on getting a runnable sample I can upload - it might be a few days given my current workload. Just have to carve out the portions of the site that are confidential.

[akiander]

Update on this ... even when running out-of-process, we just saw this web application fail on one of the two web servers. Looking closer, I see this error logged:

Log Name:      Application
Source:        .NET Runtime
Date:          3/12/2020 6:37:12 AM
Event ID:      1000
Task Category: None
Level:         Warning
Keywords:      Classic
Category: Microsoft.AspNetCore.Server.Kestrel
EventId: 22

Heartbeat took longer than "00:00:01" at "03/12/2020 10:37:12 +00:00". This could be caused by thread pool starvation.

Checking process explorer on the other web server, the thread count is pretty high (approx. 1300) so I took a minidump and checked the parallel stacks window in Visual Studio and I'm seeing most of the threads seem to be related to Azure Application Insights logging components. I'm wondering if that's a factor here.

[analogrelay]

Do you have any places where you are doing blocking calls (like Task.Result, Task.Wait, .GetAwaiter().GetResult()) in async code paths? That's a very common cause of thread-pool starvation. I'd also suggest checking our Performance Best Practices doc

[akiander]

I can't find any places in our code that is blocking. The behavior is that the app continues to build up threads until it fails as described above. I have a lot of dump files but they seem to show components related to Application Insights logging hanging onto hundreds of threads. Here's a snapshot from the most recent failure where the app was showing it had approximately 1600 threads:

I've tried adjusting App Insights logging setup but nothing seems to change this behavior. The upgrade to AspNetCore 3.1 seems to have destabilized something related to AI logging. I'm open to advice on next steps.

[davidfowl]

Something has gone completely haywire in your logic if causes app insights to spin up that many threads and the console logger to have 500 background threads.

The logging configuration might be busted.

[davidfowl]

Taking a process dump and trying to see how you ended up with 500 console loggers might show what's going on.

[akiander]

The configuration is shown above in the startup.cs and program.cs files. It attempts to follow the guidance.

The only place we differ is with our custom telemetry although that is nothing new to this app:

services.AddTransient<ITelemetryInitializer, SsoTelemetryInitializer>();

using System;
using Microsoft.ApplicationInsights.Channel;
using Microsoft.ApplicationInsights.Extensibility;
using Microsoft.AspNetCore.Http;
using Microsoft.Extensions.Configuration;

namespace Sso.Host.Logging {

    public class SsoTelemetryInitializer : ITelemetryInitializer {

        private IConfigurationRoot _configuration;
        private IHttpContextAccessor _httpContextAccessor;

        public SsoTelemetryInitializer(IConfigurationRoot configurationRoot, IHttpContextAccessor httpContextAccessor) {

            this._configuration = configurationRoot;
            this._httpContextAccessor = httpContextAccessor;

        }
        public void Initialize(ITelemetry telemetry) {

            if (!telemetry.Context.GlobalProperties.ContainsKey("CvApp")) {
                telemetry.Context.GlobalProperties.Add("CvApp", this._configuration["CvApp"] ?? "NotAvailable");
            }

            if (!telemetry.Context.GlobalProperties.ContainsKey("CvEnvironment")) {
                telemetry.Context.GlobalProperties.Add("CvEnvironment", this._configuration["CvEnvironment"] ?? "NotAvailable");
            }

            if (!telemetry.Context.GlobalProperties.ContainsKey("CvMachineName")) {
                telemetry.Context.GlobalProperties.Add("CvMachineName", Environment.MachineName ?? "NotAvailable");
            }

            if (!telemetry.Context.GlobalProperties.ContainsKey("CvUser")) {
                telemetry.Context.GlobalProperties.Add("CvUser", this._httpContextAccessor?.HttpContext?.User?.Identity?.Name ?? "NotAvailable");
            }

        }
    }
}

I guess I'll try removing this and see what happens although we depend on it for our production monitoring and triage.

Do you see anything here that might cause this?

[davidfowl]

No I would take a process dump and try to figure out what is rooting the instances of the ConsoleLogProvider (or ILoggerFactory). That might give a clue as to what is happening.

[akiander]

Seems like it is rooted by TokenCleanupHost.StartInternalAsync which is a token cleanup feature we leverage in Identity Server so I'm exploring that possibility as well.

[davidfowl]

What exactly is being rooted? Can you look at the managed memory? If you need some help looking at the memory dump I can help, send me email david.fowler at microsoft.com

[davidfowl]

Putting this in the issue since I looked at the dump.

After looking at your code I think I've figured out the issue. You have calls to BuildServiceProvider throughout your startup code some in per request locations. That will create a new service provider universe and you're also not disposing things.

Some examples on how to fix things:

services.AddSingleton<SsoClient>((provider) => {
                var svcProvider = services.BuildServiceProvider(); 
                var factory = svcProvider.GetService<ILoggerFactory>();
                var logger = factory.CreateLogger<SsoClient>(); 
                return new SsoClient(salesforceApiSettings.RestBaseUrl,
                    salesforceApiSettings.Username,
                    salesforceApiSettings.Password,
                    salesforceApiSettings.ApiKey,
                    salesforceApiSettings.ClientSecret,
                    salesforceApiSettings.ClientId,
                    logger);
            });

Should be:

services.AddSingleton<SsoClient>((provider) => {
                var factory = provider.GetService<ILoggerFactory>();
                var logger = factory.CreateLogger<SsoClient>(); 
                return new SsoClient(salesforceApiSettings.RestBaseUrl,
                    salesforceApiSettings.Username,
                    salesforceApiSettings.Password,
                    salesforceApiSettings.ApiKey,
                    salesforceApiSettings.ClientSecret,
                    salesforceApiSettings.ClientId,
                    logger);
            });

The real issue is in OnMessageReceived in the call to AddOpenIdConnect, you build the service provider potentially twice per request.

var sp = services.BuildServiceProvider();
var interactSvc = sp.GetService<IIdentityServerInteractionService>();

Should be:

var interactSvc = m.HttpContext.RequestServices.GetService<IIdentityServerInteractionService>();

[akiander]

I have removed the calls to BuildServiceProvider from startup and have the new code running in our production environment and so far it looks great. I'm going to close this out for now. I really appreciate your help on this.