Create the connection logging scope in ConnectionHandler (#2013)

- Instead of doing it on the FrameConnection only. This will
make sure all middleware logs get the connection id as part of their scope.

src/Kestrel.Core/Internal/ConnectionHandler.cs

@@ -24,6 +24,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
             _connectionDelegate = connectionDelegate;
         }
 
+        private IKestrelTrace Log => _serviceContext.Log;
+
         public void OnConnection(IFeatureCollection features)
         {
             var connectionContext = new DefaultConnectionContext(features);
@@ -51,14 +53,31 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
 
         private async Task Execute(ConnectionContext connectionContext)
         {
-            try
+            using (BeginConnectionScope(connectionContext))
             {
-                await _connectionDelegate(connectionContext);
+                Log.ConnectionStart(connectionContext.ConnectionId);
+
+                try
+                {
+                    await _connectionDelegate(connectionContext);
+                }
+                catch (Exception ex)
+                {
+                    Log.LogCritical(0, ex, $"{nameof(ConnectionHandler)}.{nameof(Execute)}() {connectionContext.ConnectionId}");
+                }
+
+                Log.ConnectionStop(connectionContext.ConnectionId);
             }
-            catch (Exception ex)
+        }
+
+        private IDisposable BeginConnectionScope(ConnectionContext connectionContext)
+        {
+            if (Log.IsEnabled(LogLevel.Critical))
             {
-                _serviceContext.Log.LogCritical(0, ex, $"{nameof(ConnectionHandler)}.{nameof(Execute)}() {connectionContext.ConnectionId}");
+                return Log.BeginScope(new ConnectionLogScope(connectionContext.ConnectionId));
             }
+
+            return null;
         }
 
         // Internal for testing

src/Kestrel.Core/Internal/FrameConnection.cs

@@ -92,92 +92,87 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
 
         private async Task ProcessRequestsAsync<TContext>(IHttpApplication<TContext> httpApplication)
         {
-            using (BeginConnectionScope())
+            try
             {
-                try
+                KestrelEventSource.Log.ConnectionStart(this);
+
+                AdaptedPipeline adaptedPipeline = null;
+                var adaptedPipelineTask = Task.CompletedTask;
+                var transport = _context.Transport;
+                var application = _context.Application;
+
+
+                if (_context.ConnectionAdapters.Count > 0)
                 {
-                    Log.ConnectionStart(ConnectionId);
+                    adaptedPipeline = new AdaptedPipeline(transport,
-                    KestrelEventSource.Log.ConnectionStart(this);
+                                                          application,
+                                                           PipeFactory.Create(AdaptedInputPipeOptions),
+                                                           PipeFactory.Create(AdaptedOutputPipeOptions));
 
-                    AdaptedPipeline adaptedPipeline = null;
+                    transport = adaptedPipeline;
-                    var adaptedPipelineTask = Task.CompletedTask;
-                    var transport = _context.Transport;
-                    var application = _context.Application;
-
-
-                    if (_context.ConnectionAdapters.Count > 0)
-                    {
-                        adaptedPipeline = new AdaptedPipeline(transport,
-                                                              application,
-                                                               PipeFactory.Create(AdaptedInputPipeOptions),
-                                                               PipeFactory.Create(AdaptedOutputPipeOptions));
-
-                        transport = adaptedPipeline;
-                    }
-
-                    // _frame must be initialized before adding the connection to the connection manager
-                    CreateFrame(httpApplication, transport, application);
-
-                    // _http2Connection must be initialized before yield control to the transport thread,
-                    // to prevent a race condition where _http2Connection.Abort() is called just as
-                    // _http2Connection is about to be initialized.
-                    _http2Connection = new Http2Connection(new Http2ConnectionContext
-                    {
-                        ConnectionId = _context.ConnectionId,
-                        ServiceContext = _context.ServiceContext,
-                        PipeFactory = PipeFactory,
-                        LocalEndPoint = LocalEndPoint,
-                        RemoteEndPoint = RemoteEndPoint,
-                        Application = application,
-                        Transport = transport
-                    });
-
-                    // Do this before the first await so we don't yield control to the transport until we've
-                    // added the connection to the connection manager
-                    _context.ServiceContext.ConnectionManager.AddConnection(_context.FrameConnectionId, this);
-                    _lastTimestamp = _context.ServiceContext.SystemClock.UtcNow.Ticks;
-
-                    if (adaptedPipeline != null)
-                    {
-                        // Stream can be null here and run async will close the connection in that case
-                        var stream = await ApplyConnectionAdaptersAsync();
-                        adaptedPipelineTask = adaptedPipeline.RunAsync(stream);
-                    }
-
-                    if (_frame.ConnectionFeatures?.Get<ITlsApplicationProtocolFeature>()?.ApplicationProtocol == "h2" &&
-                        Interlocked.CompareExchange(ref _http2ConnectionState, Http2ConnectionStarted, Http2ConnectionNotStarted) == Http2ConnectionNotStarted)
-                    {
-                        await _http2Connection.ProcessAsync(httpApplication);
-                    }
-                    else
-                    {
-                        await _frame.ProcessRequestsAsync();
-                    }
-
-                    await adaptedPipelineTask;
-                    await _socketClosedTcs.Task;
                 }
-                catch (Exception ex)
+
+                // _frame must be initialized before adding the connection to the connection manager
+                CreateFrame(httpApplication, transport, application);
+
+                // _http2Connection must be initialized before yield control to the transport thread,
+                // to prevent a race condition where _http2Connection.Abort() is called just as
+                // _http2Connection is about to be initialized.
+                _http2Connection = new Http2Connection(new Http2ConnectionContext
                 {
-                    Log.LogError(0, ex, $"Unexpected exception in {nameof(FrameConnection)}.{nameof(ProcessRequestsAsync)}.");
+                    ConnectionId = _context.ConnectionId,
-                }
+                    ServiceContext = _context.ServiceContext,
-                finally
+                    PipeFactory = PipeFactory,
+                    LocalEndPoint = LocalEndPoint,
+                    RemoteEndPoint = RemoteEndPoint,
+                    Application = application,
+                    Transport = transport
+                });
+
+                // Do this before the first await so we don't yield control to the transport until we've
+                // added the connection to the connection manager
+                _context.ServiceContext.ConnectionManager.AddConnection(_context.FrameConnectionId, this);
+                _lastTimestamp = _context.ServiceContext.SystemClock.UtcNow.Ticks;
+
+                if (adaptedPipeline != null)
                 {
-                    _context.ServiceContext.ConnectionManager.RemoveConnection(_context.FrameConnectionId);
+                    // Stream can be null here and run async will close the connection in that case
-                    DisposeAdaptedConnections();
+                    var stream = await ApplyConnectionAdaptersAsync();
-
+                    adaptedPipelineTask = adaptedPipeline.RunAsync(stream);
-                    if (_frame.WasUpgraded)
-                    {
-                        _context.ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne();
-                    }
-                    else
-                    {
-                        _context.ServiceContext.ConnectionManager.NormalConnectionCount.ReleaseOne();
-                    }
-
-                    Log.ConnectionStop(ConnectionId);
-                    KestrelEventSource.Log.ConnectionStop(this);
                 }
+
+                if (_frame.ConnectionFeatures?.Get<ITlsApplicationProtocolFeature>()?.ApplicationProtocol == "h2" &&
+                    Interlocked.CompareExchange(ref _http2ConnectionState, Http2ConnectionStarted, Http2ConnectionNotStarted) == Http2ConnectionNotStarted)
+                {
+                    await _http2Connection.ProcessAsync(httpApplication);
+                }
+                else
+                {
+                    await _frame.ProcessRequestsAsync();
+                }
+
+                await adaptedPipelineTask;
+                await _socketClosedTcs.Task;
+            }
+            catch (Exception ex)
+            {
+                Log.LogError(0, ex, $"Unexpected exception in {nameof(FrameConnection)}.{nameof(ProcessRequestsAsync)}.");
+            }
+            finally
+            {
+                _context.ServiceContext.ConnectionManager.RemoveConnection(_context.FrameConnectionId);
+                DisposeAdaptedConnections();
+
+                if (_frame.WasUpgraded)
+                {
+                    _context.ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne();
+                }
+                else
+                {
+                    _context.ServiceContext.ConnectionManager.NormalConnectionCount.ReleaseOne();
+                }
+
+                KestrelEventSource.Log.ConnectionStop(this);
             }
         }
 
@@ -497,15 +492,5 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
                 _writeTimingWrites--;
             }
         }
-
-        private IDisposable BeginConnectionScope()
-        {
-            if (Log.IsEnabled(LogLevel.Critical))
-            {
-                return Log.BeginScope(new ConnectionLogScope(ConnectionId));
-            }
-
-            return null;
-        }
     }
 }

test/Kestrel.Core.Tests/ConnectionHandlerTests.cs

@@ -0,0 +1,70 @@
+using System;
+using System.Collections.Generic;
+using System.IO.Pipelines;
+using System.Linq;
+using System.Text;
+using System.Threading.Tasks;
+using Microsoft.AspNetCore.Http.Features;
+using Microsoft.AspNetCore.Protocols.Features;
+using Microsoft.AspNetCore.Server.Kestrel.Core.Internal;
+using Microsoft.AspNetCore.Testing;
+using Xunit;
+
+namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
+{
+    public class ConnectionHandlerTests
+    {
+        [Fact]
+        public void OnConnectionCreatesLogScopeWithConnectionId()
+        {
+            var serviceContext = new TestServiceContext();
+            var tcs = new TaskCompletionSource<object>();
+            var handler = new ConnectionHandler(serviceContext, _ => tcs.Task);
+
+            var connection = new TestConnection();
+
+            handler.OnConnection(connection);
+
+            // The scope should be created
+            var scopeObjects = ((TestKestrelTrace)serviceContext.Log)
+                                    .Logger
+                                    .Scopes
+                                    .OfType<IReadOnlyList<KeyValuePair<string, object>>>()
+                                    .ToList();
+
+            Assert.Single(scopeObjects);
+            var pairs = scopeObjects[0].ToDictionary(p => p.Key, p => p.Value);
+            Assert.True(pairs.ContainsKey("ConnectionId"));
+            Assert.Equal(connection.ConnectionId, pairs["ConnectionId"]);
+
+            tcs.TrySetResult(null);
+
+            // Verify the scope was disposed after request processing completed
+            Assert.True(((TestKestrelTrace)serviceContext.Log).Logger.Scopes.IsEmpty);
+        }
+
+        private class TestConnection : FeatureCollection, IConnectionIdFeature, IConnectionTransportFeature
+        {
+            public TestConnection()
+            {
+                Set<IConnectionIdFeature>(this);
+                Set<IConnectionTransportFeature>(this);
+            }
+
+            public PipeFactory PipeFactory { get; } = new PipeFactory();
+
+            public IPipeConnection Transport { get; set; }
+            public IPipeConnection Application { get; set; }
+
+            public IScheduler InputWriterScheduler => TaskRunScheduler.Default;
+
+            public IScheduler OutputReaderScheduler => TaskRunScheduler.Default;
+
+            public Task ConnectionAborted => Task.CompletedTask;
+
+            public Task ConnectionClosed => Task.CompletedTask;
+
+            public string ConnectionId { get; set; }
+        }
+    }
+}

test/Kestrel.Core.Tests/FrameConnectionTests.cs

@@ -528,29 +528,5 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
             Assert.True(_frameConnection.TimedOut);
             Assert.True(aborted.Wait(TimeSpan.FromSeconds(10)));
         }
-
-        [Fact]
-        public async Task StartRequestProcessingCreatesLogScopeWithConnectionId()
-        {
-            _ = _frameConnection.StartRequestProcessing(new DummyApplication());
-
-            var scopeObjects = ((TestKestrelTrace)_frameConnectionContext.ServiceContext.Log)
-                                    .Logger
-                                    .Scopes
-                                    .OfType<IReadOnlyList<KeyValuePair<string, object>>>()
-                                    .ToList();
-
-            _frameConnection.OnConnectionClosed(ex: null);
-
-            await _frameConnection.StopAsync().TimeoutAfter(TimeSpan.FromSeconds(5));
-
-            Assert.Single(scopeObjects);
-            var pairs = scopeObjects[0].ToDictionary(p => p.Key, p => p.Value);
-            Assert.True(pairs.ContainsKey("ConnectionId"));
-            Assert.Equal(_frameConnection.ConnectionId, pairs["ConnectionId"]);
-
-            // Verify the scope was disposed after request processing completed
-            Assert.True(((TestKestrelTrace)_frameConnectionContext.ServiceContext.Log).Logger.Scopes.IsEmpty);
-        }
     }
 }