dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.41k stars 10k forks source link

Kestrel stops serving https (http2) requests after reboot under load #21183

Closed dv00d00 closed 3 years ago

dv00d00 commented 4 years ago

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@emails.com", 
                    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

.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 commented 4 years ago

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

dv00d00 commented 4 years ago

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:

image

Tratcher commented 4 years ago

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

dv00d00 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

image

then query cache hitting the fan

image

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 commented 4 years ago

Managed to collect trace trace.zip

dv00d00 commented 4 years ago

I've added reverse proxy in front of Kestrel.

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

Cpu from VM: image

Network from VM: image

Cpu from .net metrics: image

GC allocations: image

Lock contention: image

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 commented 4 years ago

@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 commented 4 years ago

@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 commented 4 years ago

@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:

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 commented 4 years ago

@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 commented 4 years ago

counter.zip

dv00d00 commented 4 years ago

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 commented 4 years ago

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

davidfowl commented 4 years ago

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 commented 4 years ago

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

I've visualized metrics:

ThreadPool Queue Length image

Lock contention image

dv00d00 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

Got it stack.txt

dv00d00 commented 4 years ago

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

davidfowl commented 4 years ago

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 πŸ˜„.

PS: @dv00d00 excellent debugging.

dv00d00 commented 4 years ago

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:

            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 commented 4 years ago

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 commented 4 years ago

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

rynowak commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

dv00d00 commented 4 years ago

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 commented 4 years ago

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

That may not be correct.

dv00d00 commented 4 years ago

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

CPU/RPS image

VM cpu image

Lock contention image

Allocations: image

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.

analogrelay commented 4 years ago

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 commented 4 years ago

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

davidfowl commented 4 years ago

@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 commented 4 years ago

@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 commented 4 years ago

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

davidfowl commented 4 years ago

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

davidfowl commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

Nice! Are you going to send a PR to FluffySpoon

dv00d00 commented 4 years ago

Yep, would appreciate your review tbh.