Better logging for connection errors during HTTPS handshake

src/Microsoft.AspNetCore.Server.Kestrel.Https/HttpsConnectionFilter.cs

@@ -2,11 +2,13 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
+using System.IO;
 using System.Net.Security;
 using System.Security.Cryptography.X509Certificates;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.Server.Kestrel.Filter;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Server.Kestrel.Https
 {
@@ -14,8 +16,14 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Https
     {
         private readonly HttpsConnectionFilterOptions _options;
         private readonly IConnectionFilter _previous;
+        private readonly ILogger _logger;
 
         public HttpsConnectionFilter(HttpsConnectionFilterOptions options, IConnectionFilter previous)
+            : this(options, previous, loggerFactory: null)
+        {
+        }
+
+        public HttpsConnectionFilter(HttpsConnectionFilterOptions options, IConnectionFilter previous, ILoggerFactory loggerFactory)
         {
             if (options == null)
             {
@@ -32,6 +40,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Https
 
             _options = options;
             _previous = previous;
+            _logger = loggerFactory?.CreateLogger(nameof(HttpsConnectionFilter));
         }
 
         public async Task OnConnectionAsync(ConnectionFilterContext context)
@@ -41,11 +50,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Https
             if (string.Equals(context.Address.Scheme, "https", StringComparison.OrdinalIgnoreCase))
             {
                 SslStream sslStream;
+                bool certificateRequired;
+
                 if (_options.ClientCertificateMode == ClientCertificateMode.NoCertificate)
                 {
                     sslStream = new SslStream(context.Connection);
-                    await sslStream.AuthenticateAsServerAsync(_options.ServerCertificate, clientCertificateRequired: false,
-                        enabledSslProtocols: _options.SslProtocols, checkCertificateRevocation: _options.CheckCertificateRevocation);
+                    certificateRequired = false;
                 }
                 else
                 {
@@ -81,8 +91,21 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Https
 
                             return true;
                         });
-                    await sslStream.AuthenticateAsServerAsync(_options.ServerCertificate, clientCertificateRequired: true,
-                        enabledSslProtocols: _options.SslProtocols, checkCertificateRevocation: _options.CheckCertificateRevocation);
+
+                    certificateRequired = true;
+                }
+
+                context.Connection = sslStream;
+
+                try
+                {
+                    await sslStream.AuthenticateAsServerAsync(_options.ServerCertificate, certificateRequired,
+                            _options.SslProtocols, _options.CheckCertificateRevocation);
+                }
+                catch (IOException ex)
+                {
+                    _logger?.LogInformation(1, ex, "Failed to authenticate HTTPS connection.");
+                    return;
                 }
 
                 var previousPrepareRequest = context.PrepareRequest;
@@ -98,7 +121,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Https
 
                     features.Get<IHttpRequestFeature>().Scheme = "https";
                 };
-                context.Connection = sslStream;
             }
         }
 

src/Microsoft.AspNetCore.Server.Kestrel.Https/KestrelServerOptionsHttpsExtensions.cs

@@ -7,6 +7,7 @@ using Microsoft.AspNetCore.Server.Kestrel;
 using Microsoft.AspNetCore.Server.Kestrel.Filter;
 using Microsoft.AspNetCore.Server.Kestrel.Https;
 using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Hosting
 {
@@ -83,7 +84,8 @@ namespace Microsoft.AspNetCore.Hosting
         public static KestrelServerOptions UseHttps(this KestrelServerOptions options, HttpsConnectionFilterOptions httpsOptions)
         {
             var prevFilter = options.ConnectionFilter ?? new NoOpConnectionFilter();
-            options.ConnectionFilter = new HttpsConnectionFilter(httpsOptions, prevFilter);
+            var loggerFactory = options.ApplicationServices.GetRequiredService<ILoggerFactory>();
+            options.ConnectionFilter = new HttpsConnectionFilter(httpsOptions, prevFilter, loggerFactory);
             return options;
         }
     }

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs

@@ -146,8 +146,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
             {
                 if (!_requestRejected)
                 {
+                    // SetBadRequestState logs the error.
                     SetBadRequestState(ex);
-                    Log.LogWarning(0, ex, "Connection processing ended abnormally");
                 }
             }
             catch (Exception ex)

test/Microsoft.AspNetCore.Server.KestrelTests/HttpsConnectionFilterTests.cs

@@ -17,6 +17,8 @@ using Microsoft.AspNetCore.Server.Kestrel.Filter;
 using Microsoft.AspNetCore.Server.Kestrel.Https;
 using Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure;
 using Microsoft.AspNetCore.Testing;
+using Microsoft.Extensions.Logging;
+using Moq;
 using Xunit;
 
 namespace Microsoft.AspNetCore.Server.KestrelTests
@@ -32,8 +34,7 @@ namespace Microsoft.AspNetCore.Server.KestrelTests
         public async Task CanReadAndWriteWithHttpsConnectionFilter()
         {
             var serviceContext = new TestServiceContext(new HttpsConnectionFilter(
-                    new HttpsConnectionFilterOptions
-                    { ServerCertificate = _x509Certificate2 },
+                    new HttpsConnectionFilterOptions { ServerCertificate = _x509Certificate2 },
                     new NoOpConnectionFilter())
             );
 
@@ -330,6 +331,34 @@ namespace Microsoft.AspNetCore.Server.KestrelTests
             }
         }
 
+        [Fact]
+        public async Task ClientHandshakeFailureLoggedAsInformation()
+        {
+            var logger = new HandshakerErrorLogger();
+            var mockLoggerFactory = new Mock<ILoggerFactory>(MockBehavior.Strict);
+            mockLoggerFactory.Setup(m => m.CreateLogger(nameof(HttpsConnectionFilter))).Returns(logger);
+
+            var serviceContext = new TestServiceContext(new HttpsConnectionFilter(
+                new HttpsConnectionFilterOptions { ServerCertificate = _x509Certificate2 },
+                new NoOpConnectionFilter(),
+                mockLoggerFactory.Object)
+            );
+
+            using (var server = new TestServer(App, serviceContext, _serverAddress))
+            {
+                using (await HttpClientSlim.GetSocket(new Uri($"https://localhost:{server.Port}/")))
+                {
+                    // Close socket immediately
+                }
+
+                await logger.LogTcs.Task;
+
+                Assert.Equal(1, logger.LastEventId.Id);
+                Assert.Equal(LogLevel.Information, logger.LastLogLevel);
+                mockLoggerFactory.VerifyAll();
+            }
+        }
+
         private static async Task App(HttpContext httpContext)
         {
             var request = httpContext.Request;
@@ -376,5 +405,29 @@ namespace Microsoft.AspNetCore.Server.KestrelTests
                 Assert.Null(line);
             }
         }
+
+        private class HandshakerErrorLogger : ILogger
+        {
+            public LogLevel LastLogLevel { get; set; }
+            public EventId LastEventId { get; set; }
+            public TaskCompletionSource<object> LogTcs { get; } = new TaskCompletionSource<object>();
+
+            public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
+            {
+                LastLogLevel = logLevel;
+                LastEventId = eventId;
+                LogTcs.SetResult(null);
+            }
+
+            public bool IsEnabled(LogLevel logLevel)
+            {
+                throw new NotImplementedException();
+            }
+
+            public IDisposable BeginScope<TState>(TState state)
+            {
+                throw new NotImplementedException();
+            }
+        }
     }
 }

test/shared/HttpClientSlim.cs

@@ -100,7 +100,7 @@ namespace Microsoft.AspNetCore.Testing
             }
         }
 
-        private static async Task<Socket> GetSocket(Uri requestUri)
+        public static async Task<Socket> GetSocket(Uri requestUri)
         {
             var tcs = new TaskCompletionSource<Socket>();