Aspnetcore: Kestrel stops serving https (http2) requests after reboot under load

[dv00d00]

Describe the bug

I am running Kestrel as an edge server in the Digital Ocean ( Ubuntu Docker 5:19.03.1~3 on 18.04) via docker-compose

version: '3.5'
services:

  db:
    build: ./docker/db
    command: ["--default-authentication-plugin=mysql_native_password", "--character-set-server=utf8"]
    volumes:
      - dotnet_db_data:/var/lib/mysql
    networks:
      - default
    restart: always

  dotnet:
    depends_on:
      - db
    build: .
    environment:
      ASPNETCORE_URLS: "http://+:80;https://+:443"
      ASPNETCORE_ENVIRONMENT: Production
      APPLICATION_NAME: "${APPLICATION_NAME}"
    volumes:
      - ./docker/dotnet_certs:/etc/dotnet_certs
    networks:
      - default
    ports:
      - "80:80"
      - "443:443"
    restart: always

volumes:
  dotnet_db_data: {}

networks:
  default:
    driver: bridge

The container is built with mcr.microsoft.com/dotnet/core/sdk:3.1 and mcr.microsoft.com/dotnet/core/aspnet:3.1

I am using Compression and ResponseCaching middlewares in the request pipeline.

        public void ConfigureServices(IServiceCollection services)
        {
            var deployment = DeploymentResolver.Resolve(Environment, Configuration);
            services.AddSingleton<Deployment>(deployment);

            services.AddHttpContextAccessor();
            services.TryAddScoped<IUserAgentService, UserAgentService>();
            services.TryAddScoped<IDeviceService, DeviceService>();

            var mvc = services.AddMvc(options =>
            {
                options.CacheProfiles.Add(DefinedCacheProfiles.Default, new CacheProfile
                {
                    VaryByHeader = DefinedCacheProfiles.PlatformDetectHeader,
                    Duration = 60 * 5
                });

                if (Environment.IsStaging())
                {
                    options.Filters.Add(new BasicAuth("test"));
                }
            })
            .AddJsonOptions(options => options.JsonSerializerOptions.PropertyNamingPolicy = null); ;

            if (Environment.IsDevelopment())
            {
                mvc.AddRazorRuntimeCompilation();
            }

            services.AddDbContext<TrackDbContext>(options =>
            {
                options.UseMySql(Configuration.GetConnectionString("DefaultConnection"),
                    mysql =>
                    {
                        mysql.ServerVersion(new Version(8, 0, 16), ServerType.MySql);
                        mysql.MigrationsHistoryTable("migrations_history");
                    });
            });

            services.AddResponseCaching(options => { options.UseCaseSensitivePaths = false; });
            services.AddMemoryCache(options => { });

            services.AddHttpClient();
            services.RemoveAll<IHttpMessageHandlerBuilderFilter>();

            services.Configure<GzipCompressionProviderOptions>(options =>
            {
                options.Level = CompressionLevel.Optimal;
            });

            services.AddResponseCompression(options =>
            {
                options.EnableForHttps = true;
                options.MimeTypes = new[]
                {
                    "application/atom+xml",
                    "application/javascript",
                    "application/json",
                    "application/ld+json",
                    "application/manifest+json",
                    "application/rss+xml",
                    "application/vnd.geo+json",
                    "application/vnd.ms-fontobject",
                    "application/x-font-ttf",
                    "application/x-web-app-manifest+json",
                    "application/xhtml+xml",
                    "application/xml",
                    "font/opentype",
                    "font/woff2",
                    "image/bmp",
                    "image/svg+xml",
                    "image/x-icon",
                    "text/html",
                    "text/cache-manifest",
                    "text/css",
                    "text/plain",
                    "text/vcard",
                    "text/vnd.rim.location.xloc",
                    "text/vtt",
                    "text/x-component",
                    "text/x-cross-domain-policy",
                };

                options.Providers.Add<BrotliCompressionProvider>();
                options.Providers.Add<GzipCompressionProvider>();
            });

            if (!Environment.IsDevelopment())
            {
                services.AddFluffySpoonLetsEncrypt(new LetsEncryptOptions
                {
                    Email =  "[email protected]", 
                    UseStaging = false, 
                    Domains = new[] { deployment.DNS },
                    TimeUntilExpiryBeforeRenewal = TimeSpan.FromDays(30), 
                    TimeAfterIssueDateBeforeRenewal = TimeSpan.FromDays(7), 
                    CertificateSigningRequest = new CsrInfo(),
                    KeyAlgorithm = KeyAlgorithm.ES256,
                });

                services.AddFluffySpoonLetsEncryptFileCertificatePersistence("//etc/dotnet_certs/main");
                services.AddFluffySpoonLetsEncryptMemoryChallengePersistence();
            }
        }

        public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
            if (!env.IsProduction())
            {
                app.UseDeveloperExceptionPage();
                app.UseDatabaseErrorPage();
            }

            app.UseFluffySpoonLetsEncrypt();

            app.UseHsts();
            app.UseHttpsRedirection();
            app.UseStatusCodePagesWithReExecute("/status/{0}");

            app.Use((context, next) =>
            {
                context.SetEndpoint(null);
                return next();
            });

            app.Map("/metrics", metricsApp =>
            {
                const string userName = "monitoring";
                const string password = "long-and-secure-password-for-monitoring-2";
                var valid = "Basic " + Convert.ToBase64String(Encoding.UTF8.GetBytes(userName + ":" + password));

                metricsApp.Use((context, next) =>
                {
                    if (context.Request.Headers["Authorization"] == valid)
                    {
                        return next();
                    }

                    context.Response.Headers["WWW-Authenticate"] = "Basic";
                    context.Response.StatusCode = (int) HttpStatusCode.Unauthorized;
                    return Task.CompletedTask;
                });

                metricsApp.UseMetricServer("");
            });

            app.UseResponseCompression();

            var cacheValue = $"public, max-age={30 * 24 * 60 * 60}";
            app.UseStaticFiles(new StaticFileOptions
            {
                OnPrepareResponse = ctx => { 
                    ctx.Context.Response.Headers.Append("Cache-Control", cacheValue); 
                }
            });

            app.UseRouting();

            app.UseHttpMetrics(options =>
            {
                options.InProgress.Enabled = false;
            });

            app.Use(DetectDevice);

            app.UseResponseCaching();

            app.UseEndpoints(endpoints => { endpoints.MapControllers(); });
        }

The issue was not appearing before we have started receiving increased volume of traffic (eg before 1 rps after 8 rps).

Deployment process loads latest commit from repo, builds container on the host and launches new instance docker-compose -f prod.yml up -d --build

This process restarts the running Kestrel container and after the restart, newly started instance is not handling any requests.

Cpu is low during this period (normal avg 10%, broken avg 10%).

After a series of reboots server starts to handle requests again.

To Reproduce

I am able to consistently reproduce the issues with the syntetic traffic on our staging env:

    class Program
    {
        private static readonly string[] Urls = new[]
        {
            "https://server.com/homepage",
            "https://server.com/homepage2",
            "https://server.com/homepage3",

        };

        static async Task Main(string[] args)
        {
            for (int i = 0; i < 50; i++)
            {
                Go(i + 1);
            }

            Console.ReadLine();
        }

        static async Task Go(int id)
        {
            Console.WriteLine("Running: " + id);
            var random = new Random();

            while (true)
            {
                try
                {
                    var httpClient = new HttpClient();
                    var request = new HttpRequestMessage(HttpMethod.Get, Urls[random.Next(Urls.Length)] );
                    request.Headers.Authorization = new AuthenticationHeaderValue("Basic", "YWRtaW46bG9uZy1hbmQtc2VjdXJlLXBhc3N3b3JkLWZvci1hZG1pbjI=");
                    var response = await httpClient.SendAsync(request, HttpCompletionOption.ResponseContentRead);
                    var str = await response.Content.ReadAsStringAsync();
                    // Console.WriteLine("OK");
                }
                catch (Exception e)
                {
                    Console.WriteLine(e.Message);

                    if (e.Message.Contains("SSL"))
                        Console.WriteLine(e.ToString());
                    // await Task.Delay(10);
                }
            }
        }
    }

While the fake load is running I am shutting the stack down and bringing it up again. Repro rate is around 90%

Further technical details

• ASP.NET Core version: 3.1
• Include the output of dotnet --info:

Host (useful for support):
  Version: 3.1.1
  Commit:  a1388f194c

.NET Core SDKs installed:
  No SDKs were found.

.NET Core runtimes installed:
  Microsoft.AspNetCore.App 3.1.1 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 3.1.1 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

[Tratcher]

What do the server logs say?
https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-3.1#configuration

[dv00d00]

Whenever I was able to reproduce this behavior the only logs I was getting was the default startup output:

dotnet_1  | warn: Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository[60]
dotnet_1  |       Storing keys in a directory '/root/.aspnet/DataProtection-Keys' that may not be persisted outside of the container. Protected data will be unavailable when container is destroyed.
dotnet_1  | info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
dotnet_1  |       User profile is available. Using '/root/.aspnet/DataProtection-Keys' as key repository; keys will not be encrypted at rest.
dotnet_1  | info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[58]
dotnet_1  |       Creating key {51e563a9-e6ff-427c-9345-e2c20042d581} with creation date 2020-04-24 20:48:20Z, activation date 2020-04-24 20:48:20Z, and expiration date 2020-07-23 20:48:20Z.
dotnet_1  | warn: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[35]
dotnet_1  |       No XML encryptor configured. Key {51e563a9-e6ff-427c-9345-e2c20042d581} may be persisted to storage in unencrypted form.
dotnet_1  | info: Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository[39]
dotnet_1  |       Writing data to file '/root/.aspnet/DataProtection-Keys/key-51e563a9-e6ff-427c-9345-e2c20042d581.xml'.
dotnet_1  | info: Microsoft.Hosting.Lifetime[0]
dotnet_1  |       Now listening on: http://[::]:80
dotnet_1  | info: Microsoft.Hosting.Lifetime[0]
dotnet_1  |       Now listening on: https://[::]:443
dotnet_1  | info: FluffySpoon.AspNet.LetsEncrypt.Certes.ILetsEncryptRenewalService[0]
dotnet_1  |       Application started
dotnet_1  | info: Microsoft.Hosting.Lifetime[0]
dotnet_1  |       Application started. Press Ctrl+C to shut down.
dotnet_1  | info: Microsoft.Hosting.Lifetime[0]
dotnet_1  |       Hosting environment: Staging
dotnet_1  | info: Microsoft.Hosting.Lifetime[0]
dotnet_1  |       Content root path: /app
dotnet_1  | info: FluffySpoon.AspNet.LetsEncrypt.Certificates.CertificateProvider[0]
dotnet_1  |       Checking to see if in-memory LetsEncrypt certificate needs renewal.
dotnet_1  | info: FluffySpoon.AspNet.LetsEncrypt.Certificates.CertificateProvider[0]
dotnet_1  |       Checking to see if existing LetsEncrypt certificate has been persisted and is valid.
dotnet_1  | info: FluffySpoon.AspNet.LetsEncrypt.Certificates.CertificateProvider[0]
dotnet_1  |       A persisted non-expired LetsEncrypt certificate was found and will be used.

and a several minutes of silence after

On a very rare occasion, I was getting

failed to receive a heartbeat in 1 second, looks like a threadpool starvation ( I was not able to copy the actual message yet)

I have disabled caching middleware and now getting the issue 100% of the time. (Will publish debug level logs in a moment)

So looks like a bunch of HTTP client (50 in my case) simultaneously sending 50 requests, if cache is not populated all of those requests are hitting some sort of lock contention.

There is a screenshot of the lock contention graphs from the production box which is running fine now:

[Tratcher]

Ah, that's progress. A process dump or attaching a debugger would be what you need to see where those threads are stuck.

[dv00d00]

Debug level logs

dotnet_1  | warn: Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository[60]
dotnet_1  |       Storing keys in a directory '/root/.aspnet/DataProtection-Keys' that may not be persisted outside of the container. Protected data will be unavailable when container is destroyed.
dotnet_1  | info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
dotnet_1  |       User profile is available. Using '/root/.aspnet/DataProtection-Keys' as key repository; keys will not be encrypted at rest.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver[53]
dotnet_1  |       Repository contains no viable default key. Caller should generate a key with immediate activation.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider[57]
dotnet_1  |       Policy resolution states that a new key should be added to the key ring.
dotnet_1  | info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[58]
dotnet_1  |       Creating key {6550b92f-a449-4cb0-8a66-feb84141dd52} with creation date 2020-04-24 20:58:45Z, activation date 2020-04-24 20:58:45Z, and expiration date 2020-07-23 20:58:45Z.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[32]
dotnet_1  |       Descriptor deserializer type for key {6550b92f-a449-4cb0-8a66-feb84141dd52} is 'Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Version=3.1.3.0, Culture=neutral, PublicKeyToken=adb9793829ddae60'.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[34]
dotnet_1  |       No key escrow sink found. Not writing key {6550b92f-a449-4cb0-8a66-feb84141dd52} to escrow.
dotnet_1  | warn: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[35]
dotnet_1  |       No XML encryptor configured. Key {6550b92f-a449-4cb0-8a66-feb84141dd52} may be persisted to storage in unencrypted form.
dotnet_1  | info: Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository[39]
dotnet_1  |       Writing data to file '/root/.aspnet/DataProtection-Keys/key-6550b92f-a449-4cb0-8a66-feb84141dd52.xml'.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[23]
dotnet_1  |       Key cache expiration token triggered by 'CreateNewKey' operation.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository[37]
dotnet_1  |       Reading data from file '/root/.aspnet/DataProtection-Keys/key-6550b92f-a449-4cb0-8a66-feb84141dd52.xml'.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[18]
dotnet_1  |       Found key {6550b92f-a449-4cb0-8a66-feb84141dd52}.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver[13]
dotnet_1  |       Considering key {6550b92f-a449-4cb0-8a66-feb84141dd52} with expiration date 2020-07-23 20:58:45Z as default key.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.TypeForwardingActivator[0]
dotnet_1  |       Forwarded activator type request from Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Version=3.1.3.0, Culture=neutral, PublicKeyToken=adb9793829ddae60 to Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Culture=neutral, PublicKeyToken=adb9793829ddae60
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ManagedAuthenticatedEncryptorFactory[11]
dotnet_1  |       Using managed symmetric algorithm 'System.Security.Cryptography.Aes'.
db_1      | 2020-04-24T20:58:46.046834Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: '/var/run/mysqld/mysqlx.sock' bind-address: '::' port: 33060
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ManagedAuthenticatedEncryptorFactory[10]
dotnet_1  |       Using managed keyed hash algorithm 'System.Security.Cryptography.HMACSHA256'.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider[2]
dotnet_1  |       Using key {6550b92f-a449-4cb0-8a66-feb84141dd52} as the default key.
dotnet_1  | dbug: Microsoft.AspNetCore.DataProtection.Internal.DataProtectionHostedService[0]
dotnet_1  |       Key ring with default key {6550b92f-a449-4cb0-8a66-feb84141dd52} was loaded during application startup.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer[2]
dotnet_1  |       Failed to locate the development https certificate at '(null)'.
dotnet_1  | info: Microsoft.Hosting.Lifetime[0]
dotnet_1  |       Now listening on: http://[::]:80
dotnet_1  | info: Microsoft.Hosting.Lifetime[0]
dotnet_1  |       Now listening on: https://[::]:443
dotnet_1  | dbug: Microsoft.AspNetCore.Hosting.Diagnostics[0]
dotnet_1  |       Loaded hosting startup assembly WebApplication
dotnet_1  | info: FluffySpoon.AspNet.LetsEncrypt.Certes.ILetsEncryptRenewalService[0]
dotnet_1  |       Application started
dotnet_1  | info: Microsoft.Hosting.Lifetime[0]
dotnet_1  |       Application started. Press Ctrl+C to shut down.
dotnet_1  | info: Microsoft.Hosting.Lifetime[0]
dotnet_1  |       Hosting environment: Staging
dotnet_1  | info: Microsoft.Hosting.Lifetime[0]
dotnet_1  |       Content root path: /app
dotnet_1  | dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
dotnet_1  |       Hosting started
dotnet_1  | info: FluffySpoon.AspNet.LetsEncrypt.Certificates.CertificateProvider[0]
dotnet_1  |       Checking to see if in-memory LetsEncrypt certificate needs renewal.
dotnet_1  | info: FluffySpoon.AspNet.LetsEncrypt.Certificates.CertificateProvider[0]
dotnet_1  |       Checking to see if existing LetsEncrypt certificate has been persisted and is valid.
dotnet_1  | info: FluffySpoon.AspNet.LetsEncrypt.Certificates.CertificateProvider[0]
dotnet_1  |       A persisted non-expired LetsEncrypt certificate was found and will be used.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5B" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5C" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5D" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5E" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5F" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5G" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5H" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5B" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5C" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5D" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5E" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5F" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5G" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5H" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5I" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5J" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5K" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5L" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5M" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5N" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5O" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5P" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5Q" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5R" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5S" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5T" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5U" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G5V" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G60" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G61" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G62" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G63" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G64" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G65" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G66" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G67" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G68" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G69" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6A" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6B" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6C" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6D" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6E" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6F" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6G" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6H" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6I" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6J" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6K" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6L" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6M" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6N" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6O" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6P" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6Q" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6R" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6S" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5I" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5J" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5K" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5L" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5M" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5N" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5O" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5P" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5Q" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5G" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5R" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5S" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5I" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5T" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5U" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G5V" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G60" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G61" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G62" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G63" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G64" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5Q" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G65" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5R" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G66" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G67" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G68" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G69" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5V" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6A" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6B" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6C" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6D" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G63" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6E" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6F" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6G" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6H" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6I" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6J" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G69" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6K" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6A" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6L" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6B" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6M" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6N" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6O" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6P" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6Q" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6G" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6R" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6S" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6I" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5C" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5B" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5D" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5F" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5E" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5H" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6J" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6T" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6U" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G6V" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G70" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G71" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G72" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G73" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G74" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G75" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G76" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G77" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5J" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5K" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5L" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5M" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5N" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5O" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5P" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5S" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5T" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G5U" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G60" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G61" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G62" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G64" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G65" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G66" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G67" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G68" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6C" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6D" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6E" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6F" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6H" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6T" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6U" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6K" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G6V" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G70" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G71" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G72" started.
^Adotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G73" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G74" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G75" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G76" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G77" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G78" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G79" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7A" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7B" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7C" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7D" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7E" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7F" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7G" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7H" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7I" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7J" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7K" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7L" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7M" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7N" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7O" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7P" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7Q" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7R" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7S" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7T" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7U" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G7V" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G80" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G81" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G82" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G83" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G84" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G85" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G86" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[39]
dotnet_1  |       Connection id "0HLV8I93V3G87" accepted.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6L" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6N" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6M" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6O" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6P" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6Q" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6R" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6S" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G6T" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G78" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G79" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7A" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G70" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7B" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7C" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G71" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7D" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G72" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7E" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G73" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7F" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G74" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7G" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7H" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7I" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G77" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7J" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G78" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7K" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7L" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7M" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7N" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7O" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7P" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7Q" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7R" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7S" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7T" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7U" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G7L" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G7V" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G7M" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G80" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G81" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G82" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G7O" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G83" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G7P" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G84" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G85" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G7R" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G86" started.
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
dotnet_1  |       Connection id "0HLV8I93V3G7S" sending FIN because: "The connection was aborted by the application via ConnectionContext.Abort()."
dotnet_1  | dbug: Microsoft.AspNetCore.Server.Kestrel[1]
dotnet_1  |       Connection id "0HLV8I93V3G87" started.

[dv00d00]

I will try to repro on my dev box under the debugger, will attempt to get dump out of container it that won't work

[Tratcher]

Weird, those connections don't even show that they've received any requests. Are those supposed to be https? Is it having trouble getting the FluffySpoon cert for the ssl channel?

[dv00d00]

Those are https indeed.

FluffySpoon is a lets encrypt cert renewal middleware, it got the certificate into a static variable before the server started listening to requests. ( according to logs at least )
(https://github.com/ffMathy/FluffySpoon.AspNet.LetsEncrypt/blob/master/src/FluffySpoon.AspNet.LetsEncrypt/KestrelOptionsSetup.cs)

I was not able to reproduce exact behavior locally, neither attach debugger to a remote docker container.

I did run damn thing under the profiler (windows, development). When a fresh instance is struck with 100 or so requests, there is a huge lock contention over entity framework context GetModel

then query cache hitting the fan

I am quite new at reading it though, I will try to grab proper trace from the thing in the docker, would appreciate any advice on how to do it.

[dv00d00]

Managed to collect trace
trace.zip

[dv00d00]

I've added reverse proxy in front of Kestrel.

Got a decent amount of metrics, change is very obvious.

Cpu from VM:

Network from VM:

Cpu from .net metrics:

GC allocations:

Lock contention:

A brief history of changes:

1. Change of VM (1 core 2 GB Ram -> 2 cores 4 GB Ram)
2. Reverse proxy added
   I've removed static files, compression, hsts, https redirection middlewares from Kestrel.
   Added UseForwardedHeaders.
   Changed hack for response caching (previously I was adding extra request header, now I am overwriting UserAgent)
   Turned off https.

[davidfowl]

@dv00d00 it sounds like you have a typical sync over async issue where your thread pool is being starved. It's likely caused by something in process blocking, if you're willing to, I'd like to help you debug this issue. To verify that it might indeed be thread pool starvation can you run dotnet counters inside of your container on the application that having this problem? The counters to look at would be the thread pool queue count.

[dv00d00]

@davidfowl will do. Are we interested in just my code or the whole setup which was experiencing thread pool starvation? (I assume the whole setup).

I've attached a graph of lock contention above, it shows a significant drop after I've removed some of middlewares from pipeline.

[davidfowl]

@davidfowl will do. Are we interested in just my code or the whole setup which was experiencing thread pool starvation? (I assume the whole setup).

Yes, I'm interesting in a couple of things:

• What components are "slow" here. Do you have anything blocking threads? Is it the lock contention?
• Between a dump and a trace, what things tools can we build to improve the diagnostics of these cases (we're working on a few specific async aware diagnostics tools that I want to try out on your scenario).

If you remove the load balancer and also removed the middleware does it improve things or did it still get stuck? Also do you have a process dump when things are stuck? (don't share it here, it has sensitive information).

[dv00d00]

@davidfowl

Due to the thread blocking: I am almost certain that there are no blocking calls (I am awaiting every async method or clear usage of lock instructions). The app is pretty simple, a bunch of controllers with views, some API calls via IHttpClientFactory. Views are a bit involved though, a lot of partials, some usage of ICompositeViewEngine.GetView here and there and that is basically it.

Full package list

<PackageReference Include="FluffySpoon.AspNet.LetsEncrypt" Version="1.146.0" />
<PackageReference Include="Microsoft.AspNetCore.Diagnostics.EntityFrameworkCore" Version="3.1.3" />
<PackageReference Include="Microsoft.AspNetCore.Mvc.Razor.RuntimeCompilation" Version="3.1.3" />
<PackageReference Include="Serilog.AspNetCore" Version="3.2.0" />
<PackageReference Include="Serilog.Sinks.Loggly" Version="5.4.0" />
<PackageReference Include="prometheus-net.AspNetCore" Version="3.5.0" />
<PackageReference Include="prometheus-net.DotNetRuntime" Version="3.3.1" />
<PackageReference Include="Microsoft.EntityFrameworkCore.Design" Version="3.1.3" />
<PackageReference Include="Pomelo.EntityFrameworkCore.MySql" Version="3.1.1" />

Due to the tools, I've never had to deal with such in-depth performance profiling yet, dotnet-dump was impressive, PerfView is awful. In theory, something that would throw on calling Task.GetResult could be useful in debug mode.

I've managed to collect counters from the repro env, which is in exact shape when it happened in production. A few observations are if I will hit an with a single request from the browser before launching a load upon it, everything is slow (I've disabled cache) but works. The issue appears only if I hit the app with ~50 simultaneous requests from the load gen in the header of this issue.

[counter.zip](https://github.com/dotnet/aspnetcore/files/4534079/counter.zip)

thanks for working with me on Saturday

[dv00d00]

counter.zip

[dv00d00]

For this counter log, I've collected metrics from the case when I initially hit the app with a bunch of requests. I've stopped load, waited till I was able to get success and then launched another test run.

[dv00d00]

Due to the dump, any advice on how and when to get it ?

[davidfowl]

Due to the thread blocking: I am almost certain that there are no blocking calls (I am awaiting every async method or clear usage of lock instructions)

Libraries you are using might not be as diligent as you are.

Due to the tools, I've never had to deal with such in-depth performance profiling yet, dotnet-dump was impressive, PerfView is awful. In theory, something that would throw on calling Task.GetResult could be useful in debug mode.

Visual Studio also supports nettrace files! 😄

I've managed to collect counters from the repro env, which is in exact shape when it happened in production. A few observations are if I will hit an with a single request from the browser before launching a load upon it, everything is slow (I've disabled cache) but works. The issue appears only if I hit the app with ~50 simultaneous requests from the load gen in the header of this issue.

Thats very interesting it sounds like an the threadpool might be bombarded and requests are queued not being dequeued because there's a low number of threads to begin with. That usually only matters when blocking but it could also be due to things like Parallel.For/Foreach etc.

Due to the dump, any advice on how and when to get it ?

If you can reproduce it on demand in production, you need to add the dotnet dump tool to your container image so that you can exec into the container and capture it. Is that possible?

[dv00d00]

I am able to reproduce this thing easily, so dump is 100% possible

I've visualized metrics:

ThreadPool Queue Length

Lock contention

[dv00d00]

Due to the temp solution, can anyone validate this:

Some sort of initialization is happening during the first HTTP request to the server. This initialization requires a lock. If the uninitialized server is getting a bunch of requests it will spawn a thread for each, normally only a thread per core will be used.

A bunch of threads waiting to be dispatched crush cpu, nothing happens at this stage.

A regular page on my site is referencing ~15 static assets. During a peak, if I deploy a new version, it will start processing tcp traffic across previously active and new users.

If I somehow massage the server before exposing it to the world it might help. Docker health check might work if I will send a bunch of requests (sequentially) on the server before exposing it.

[davidfowl]

I am able to reproduce this thing easily, so dump is 100% possible

Perfect, can you get a dump? In your docker file, if you're doing a multi-statge build you can use the build stage to install the dotnet dump tool then copy it over to the runtime image. After you do that, you should be able to exec into the container and run dotnet-dump on the tool to capture it inside of the container. I'd recommand capturing the dump an looking at it inside of the container since that's easier.

Then run dotnet-dump analyze {dumpfile} to get the repl and run:

clrstack -all

That'll show all managed stacks. Paste the output in here.

[davidfowl]

This is what you can put in your docker file to install the tools (assuming you're doing a multi-stage build)

FROM mcr.microsoft.com/dotnet/core/sdk:3.1 AS build-env

RUN dotnet tool install dotnet-dump --tool-path /tools
RUN dotnet tool install dotnet-counters --tool-path /tools
RUN dotnet tool install dotnet-trace --tool-path /tools

WORKDIR /app

# Build runtime image
FROM mcr.microsoft.com/dotnet/core/aspnet:3.1

COPY --from=build-env /tools /tools

[dv00d00]

Got it
stack.txt

[dv00d00]

looks like System.Net.Http.TLSCertificateExtensions.BuildNewChain blocks

[davidfowl]

Yep https://github.com/dotnet/runtime/blob/dbc7fc6ec8d3812cef5eee5d0a9492e0c1fc37e1/src/libraries/System.Security.Cryptography.X509Certificates/src/Internal/Cryptography/Pal.Unix/CertificateAssetDownloader.cs#L99-L124

This has plagued several issues now and it might be time to discuss an alternative. I'm not even sure its possible to work around 😢 .

Look @bartonjs its our friend again 😄.

• https://github.com/dotnet/runtime/issues/24527
• https://github.com/dotnet/runtime/issues/31664

PS: @dv00d00 excellent debugging.

[dv00d00]

Well..., 🛡️

Does it mean do not use Kestrel as an edge server until SslStream is fixed for Unix? Any chance it will be fixed as a prerequisite for YARP?

I took a brief look at the source code for ssl stream, does it download cert for request Kestrel handles?

I mean maybe there is a way to cache it somehow before starting port listening?

This did not work:
```c#
var bytes = await File.ReadAllBytesAsync("//etc/dotnet_certs/main_Site");
using (var cert = new X509Certificate2(bytes, "FluffySpoon"))
using (var chain = new X509Chain(true))
{

            chain.Build(cert);
        }

```

Thanks for replies on weekend @davidfowl

[davidfowl]

I don't see an obvious way to disable this download. This has come up several times with lets encrypt and we're going to need to revisit this solution.

It's happening every time you boot the container right? I believe they are stored on disk and that might be the reason for his behavior? Let me do some more digging on a potential workaround.

[davidfowl]

BTW please file an issue on dotnet/runtime. This needs to be fixed in SSlStream and X509Chain

[rynowak]

Does this get better if we use .pem instead of .pfx? That's something that's possible today with a workaround, and should become easy in .NET 5.

[davidfowl]

I don't know but I don't think so, i's PEM just a different way to encode the same cert information? It's this super jank logic that exists in building the cert chain where the API uses HttpClient (via reflection) to download the revocation list. I'm not even sure you can disable it looking at the code...

[rynowak]

note: I am super not an expert on any of these things... My understanding is that .pem as a format can contain the entire cert chain.

https://www.digicert.com/kb/ssl-support/pem-ssl-creation.htm

[dv00d00]

_note: I am super not an expert on any of these things..._ My understanding is that .pem as a format can contain the entire cert chain.

https://www.digicert.com/kb/ssl-support/pem-ssl-creation.htm

This is what certbot downloads for nginx

This directory contains your keys and certificates.

`privkey.pem`  : the private key for your certificate.
`fullchain.pem`: the certificate file used in most server software.
`chain.pem`    : used for OCSP stapling in Nginx >=1.3.7.
`cert.pem`     : will break many server configurations, and should not be used
                 without reading further documentation (see link below).

WARNING: DO NOT MOVE OR RENAME THESE FILES!
         Certbot expects these files to remain in this location in order
         to function properly!

We recommend not moving these files. For more information, see the Certbot
User Guide at https://certbot.eff.org/docs/using.html#where-are-my-certificates.

[davidfowl]

note: I am super not an expert on any of these things... My understanding is that .pem as a format can contain the entire cert chain.

Good to know 😄 .I also am not an expert in certificates.

[dv00d00]

nginx setup which I've copied from some article also uses fullchain.pem in its config

ssl_certificate /etc/letsencrypt/live/domain.name/fullchain.pem;
ssl_certificate_key /etc/letsencrypt/live/domain.name/privkey.pem;
include /etc/nginx-conf/ssl-params/options-ssl-nginx.conf;
ssl_dhparam /etc/nginx-conf/ssl-params/ssl-dhparams.pem;

will definitely try it tomorrow

[davidfowl]

We should look into making ASP.NET Core work with certbot, or at least understand how to connect the two and document it.

[dv00d00]

btw the lib I am using for LetsEncrypt is storing the key in PEM, and by looking at the certificate acquisition code it attempts to get the full chain one.

https://github.com/ffMathy/FluffySpoon.AspNet.LetsEncrypt/blob/65eb855c6ee36290d4f31cb6ac6d3c9508abd966/src/FluffySpoon.AspNet.LetsEncrypt/Certes/LetsEncryptClient.cs#L80

I've checked how the certificate looks in PEM, it does include fullchain.

Bag Attributes
    localKeyID: 45 3F A5 E2 78 44 18 85 25 42 5E 2B 76 A2 F6 E7 A9 B1 71 B9 
    friendlyName: FluffySpoonAspNetLetsEncryptCertificate
Key Attributes: <No Attributes>
-----BEGIN PRIVATE KEY-----
****censored****
-----END PRIVATE KEY-----
Bag Attributes
    localKeyID: 45 3F A5 E2 78 44 18 85 25 42 5E 2B 76 A2 F6 E7 A9 B1 71 B9 
    friendlyName: FluffySpoonAspNetLetsEncryptCertificate
subject=/CN=dotnet-web-staging.censored.com
issuer=/C=US/O=Let's Encrypt/CN=Let's Encrypt Authority X3
-----BEGIN CERTIFICATE-----
MIIEpjCCA46gAwIBAgISBASS7/Sjc3Obeu3GTWf/4W1wMA0GCSqGSIb3DQEBCwUA
==
-----END CERTIFICATE-----
Bag Attributes: <Empty Attributes>
subject=/C=US/O=Let's Encrypt/CN=Let's Encrypt Authority X3
issuer=/O=Digital Signature Trust Co./CN=DST Root CA X3
-----BEGIN CERTIFICATE-----
MIIEkjCCA3qgAwIBAgIQCgFBQgAAAVOFc2oLheynCDANBgkqhkiG9w0BAQsFADA/
==
-----END CERTIFICATE-----

[davidfowl]

~Does that include the CRL? That’s the thing being downloaded~

That may not be correct.

[dv00d00]

2 days passed since the migration to Nginx. Got some fresh graphs

CPU/RPS

VM cpu

Lock contention

Allocations:

What changed: http2 -> http1.1; no static files; no compression; added an extra container for nginx.

As for the bugreport itself, looks like it does not relate to Kestrel, except maybe the issue with LetsEncrypt certificates on Unix should be highlighted to save other people some hair.

[anurse]

Triage: Queuing for 5.0. There is runtime work that needs to happen first (there are discussions planned to resolve this). @davidfowl let's make sure the outcome of that meeting and any action for ASP.NET Core gets captured clearly on this issue so that we know what to do when it comes back up for planning in a 5.0 preview.

[davidfowl]

Assign this to me. I’m going to drive the fixes to solve this issue

[davidfowl]

@dv00d00 Just an update, I have a pretty good understanding of the issue and I'll keep you posted with the progress made. I'll also want you to try kestrel again at some point and remove nginx 😄

[davidfowl]

@dv00d00 Are you willing to try something out for me? I want to see if there's a workaround we can document and I want you to try again.

[dv00d00]

Sure, still have a repro branch by my side @davidfowl

[davidfowl]

We're going to need to make a change to FluffySpoonLetsEncrypt.

[davidfowl]

I'm looking for an extensibility point in the APIs. Basically what I want you to try is building the cert chain whenever a certificate is retrieved on the background thread.

Do you know if there's a way to hook in and get the certificate before it gets passed to Kestrel? I see some ways but it requires wrapping a service.

[dv00d00]

I'm ok with including FluffySpoonLetsEncrypt as a project reference, we can use the raw cert file it creates without it being involved at all. If the workaround works I'll submit a fix pr to the https://github.com/ffMathy/FluffySpoon.AspNet.LetsEncrypt repo

[davidfowl]

OK so this logic that you wrote here:

https://github.com/dotnet/aspnetcore/issues/21183#issuecomment-619579627

You basically need to replicate that but I would copy this logic:

https://github.com/dotnet/runtime/blob/4f84429fb44801b841c052505935a3cd14da18e2/src/libraries/Common/src/System/Net/Http/TlsCertificateExtensions.cs#L77-L97

```C#
var chain = new X509Chain();
chain.ChainPolicy.VerificationFlags = X509VerificationFlags.AllFlags;
chain.ChainPolicy.RevocationFlag = X509RevocationFlag.ExcludeRoot;
chain.ChainPolicy.RevocationMode = X509RevocationMode.NoCheck;

// We're not doing anything client side
// if (includeClientApplicationPolicy)
// {
// chain.ChainPolicy.ApplicationPolicy.Add(s_clientCertOidInst);
//}

if (chain.Build(certificate))
{
return chain;
}
else
{
chain.Dispose();
return null;
}
```

Run this code here https://github.com/ffMathy/FluffySpoon.AspNet.LetsEncrypt/blob/02b617896e2ab394cb185a77b9d6f48abe6e5e12/src/FluffySpoon.AspNet.LetsEncrypt/Certificates/CertificateProvider.cs#L80

After getting the cert, Build the chain here.

[davidfowl]

It seems like there's a race condition in this library on startup where the cert could be null (or maybe I'm missing something...)

[dv00d00]

Oh wow it actually worked!

I've disabled fluffyspoon (services and middleware). The cert was already persisted to disk. I've added this method to Program.cs

        private static async Task<X509Certificate2> Build()
        {
            var bytes = await File.ReadAllBytesAsync("//etc/dotnet_certs/main_Site");
            var certificate = new X509Certificate2(bytes, "FluffySpoon");
            var chain = new X509Chain
            {
                ChainPolicy =
                {
                    VerificationFlags = X509VerificationFlags.AllFlags,
                    RevocationFlag = X509RevocationFlag.ExcludeRoot,
                    RevocationMode = X509RevocationMode.NoCheck
                }
            };

            if (chain.Build(certificate))
            {
                return certificate;
            }
            else
            {
                chain.Dispose();
                return null;
            }
        }

The used it

            var hostBuilder = Host.CreateDefaultBuilder(args)
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder
                        .ConfigureKestrel(options =>
                        {
                            options.Limits.KeepAliveTimeout = TimeSpan.FromSeconds(60);
                            options.ConfigureHttpsDefaults(o =>
                            {
                                o.ServerCertificate = cert;
                            });
                        })
                        .UseStartup<Startup>()
                        .UseSerilog();
                });

10/10 reboots under load were able to handle requests. Slower than expected, but ramping up to full speed in 20 seconds or so. The entity framework produces a lot of lock contention I believe.

When commented out

            var chain = new X509Chain
            {
                ChainPolicy =
                {
                    VerificationFlags = X509VerificationFlags.AllFlags,
                    RevocationFlag = X509RevocationFlag.ExcludeRoot,
                    RevocationMode = X509RevocationMode.NoCheck
                }
            };

            if (chain.Build(certificate))
            {
                return certificate;
            }
            else
            {
                chain.Dispose();
                return null;
            }
        }

server was not able to process any requests.

[davidfowl]

Nice! Are you going to send a PR to FluffySpoon

[dv00d00]

Yep, would appreciate your review tbh.

[dv00d00]

I am also curious about what was going on with thread pool starvation in my case. Am I right saying that all requests on a fresh/unvalidated certificate ended up querying cert status from LetsEncrypt servers and starved threadpool?

Or the certificate checks were made on a per request basis?

[davidfowl]

Am I right saying that all requests on a fresh/unvalidated certificate ended up querying cert status from LetsEncrypt servers and starved threadpool?

Even though the full chain is being requested we still validate it but this is what happens:

• We get a pfx file with the full cert chain
• We feed that cert into X509Certificate2 type which only grabs the first https cert not the full chain (we don't have a way to represent the validated chain)
• The logic then tries to download the full cert chain (per connection!), it does this synchronously.
• It caches the cert chain on disk, which is ephemeral inside of the container....

All badness.

[dv00d00]

Thanks for the review guys, both PRs (https://github.com/natemcmaster/LetsEncrypt/pull/81 and https://github.com/ffMathy/FluffySpoon.AspNet.LetsEncrypt/pull/71) are merged and will be released soon. I am not aware of any other community projects aimed at acme cert providers.

This whole story rendered that SSL could be tricky and assuming that SslStream internals will change in the future this could lead to other similar issues.

Idk, I'd be happy to see support from the dotnet team on the LestsEncrypt side. Having SSL benchmarks with popular community libs is a great starting point as @davidfowl suggested. Dotnet foundation membership is better. Builtin support is best imo.

This issue could be closed I believe.

Really interested if there will be any further steps and if I can help somehow.

This was a wild ride.

[davidfowl]

This whole story rendered that SSL could be tricky and assuming that SslStream internals will change in the future this could lead to other similar issues.

Yes this great issue investigation spawned a set of work that I have tracked here https://github.com/dotnet/aspnetcore/issues/21512. 5.0 should have this situation dramatically improved.

@bartonjs is our certificate crypto export and we're looking at ways to represent a "pre-validated" certificate chain for these scenarios to avoid this in the future.

[BrennanConroy]

@davidfowl Do we believe this issue can be closed now for 5.0?

[davidfowl]

Sorta, but I need to merge this https://github.com/dotnet/aspnetcore/pull/24935 for it to be done done