Add support for connection scopes if logging is enabled (#1953)

* Add support for connection scopes if logging is enabled
- Don't create a scope if logging isn't on
- Copied the pattern we use in Hosting

src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/ConnectionLogScope.cs

@@ -0,0 +1,63 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using System.Collections;
+using System.Collections.Generic;
+using System.Globalization;
+
+namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
+{
+    public class ConnectionLogScope : IReadOnlyList<KeyValuePair<string, object>>
+    {
+        private readonly string _connectionId;
+
+        private string _cachedToString;
+
+        public ConnectionLogScope(string connectionId)
+        {
+            _connectionId = connectionId;
+        }
+
+        public KeyValuePair<string, object> this[int index]
+        {
+            get
+            {
+                if (index == 0)
+                {
+                    return new KeyValuePair<string, object>("ConnectionId", _connectionId);
+                }
+
+                throw new ArgumentOutOfRangeException(nameof(index));
+            }
+        }
+
+        public int Count => 1;
+
+        public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
+        {
+            for (int i = 0; i < Count; ++i)
+            {
+                yield return this[i];
+            }
+        }
+
+        IEnumerator IEnumerable.GetEnumerator()
+        {
+            return GetEnumerator();
+        }
+
+        public override string ToString()
+        {
+            if (_cachedToString == null)
+            {
+                _cachedToString = string.Format(
+                    CultureInfo.InvariantCulture,
+                    "ConnectionId:{0}",
+                    _connectionId);
+            }
+
+            return _cachedToString;
+        }
+    }
+}

src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs

@@ -2,8 +2,10 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
+using System.Collections;
 using System.Collections.Generic;
 using System.Diagnostics;
+using System.Globalization;
 using System.IO;
 using System.Threading;
 using System.Threading.Tasks;
@@ -79,72 +81,75 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
 
         public void StartRequestProcessing<TContext>(IHttpApplication<TContext> application)
         {
-            _lifetimeTask = ProcessRequestsAsync<TContext>(application);
+            _lifetimeTask = ProcessRequestsAsync(application);
         }
 
         private async Task ProcessRequestsAsync<TContext>(IHttpApplication<TContext> application)
         {
-            try
+            using (BeginConnectionScope())
             {
-                Log.ConnectionStart(ConnectionId);
+                try
-                KestrelEventSource.Log.ConnectionStart(this, _context.ConnectionInformation);
-
-                AdaptedPipeline adaptedPipeline = null;
-                var adaptedPipelineTask = Task.CompletedTask;
-                var input = _context.Input.Reader;
-                var output = _context.Output;
-
-                if (_context.ConnectionAdapters.Count > 0)
                 {
-                    adaptedPipeline = new AdaptedPipeline(input,
+                    Log.ConnectionStart(ConnectionId);
-                                                          output,
+                    KestrelEventSource.Log.ConnectionStart(this, _context.ConnectionInformation);
-                                                          PipeFactory.Create(AdaptedInputPipeOptions),
-                                                          PipeFactory.Create(AdaptedOutputPipeOptions),
-                                                          Log);
 
-                    input = adaptedPipeline.Input.Reader;
+                    AdaptedPipeline adaptedPipeline = null;
-                    output = adaptedPipeline.Output;
+                    var adaptedPipelineTask = Task.CompletedTask;
+                    var input = _context.Input.Reader;
+                    var output = _context.Output;
+
+                    if (_context.ConnectionAdapters.Count > 0)
+                    {
+                        adaptedPipeline = new AdaptedPipeline(input,
+                                                              output,
+                                                              PipeFactory.Create(AdaptedInputPipeOptions),
+                                                              PipeFactory.Create(AdaptedOutputPipeOptions),
+                                                              Log);
+
+                        input = adaptedPipeline.Input.Reader;
+                        output = adaptedPipeline.Output;
+                    }
+
+                    // _frame must be initialized before adding the connection to the connection manager
+                    CreateFrame(application, input, output);
+
+                    // 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);
+                    }
+
+                    await _frame.ProcessRequestsAsync();
+                    await adaptedPipelineTask;
+                    await _socketClosedTcs.Task;
                 }
-
+                catch (Exception ex)
-                // _frame must be initialized before adding the connection to the connection manager
-                CreateFrame(application, input, output);
-
-                // 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
+                    Log.LogError(0, ex, $"Unexpected exception in {nameof(FrameConnection)}.{nameof(ProcessRequestsAsync)}.");
-                    var stream = await ApplyConnectionAdaptersAsync();
-                    adaptedPipelineTask = adaptedPipeline.RunAsync(stream);
                 }
-
+                finally
-                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();
+                    _context.ServiceContext.ConnectionManager.RemoveConnection(_context.FrameConnectionId);
-                }
+                    DisposeAdaptedConnections();
-                else
-                {
-                    _context.ServiceContext.ConnectionManager.NormalConnectionCount.ReleaseOne();
-                }
 
-                Log.ConnectionStop(ConnectionId);
+                    if (_frame.WasUpgraded)
-                KestrelEventSource.Log.ConnectionStop(this);
+                    {
+                        _context.ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne();
+                    }
+                    else
+                    {
+                        _context.ServiceContext.ConnectionManager.NormalConnectionCount.ReleaseOne();
+                    }
+
+                    Log.ConnectionStop(ConnectionId);
+                    KestrelEventSource.Log.ConnectionStop(this);
+                }
             }
         }
 
@@ -454,5 +459,15 @@ 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/Microsoft.AspNetCore.Server.Kestrel.Core.Tests/FrameConnectionTests.cs

@@ -3,6 +3,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal;
@@ -529,5 +530,26 @@ 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());
+
+            _frameConnection.OnConnectionClosed(ex: null);
+
+            await _frameConnection.StopAsync().TimeoutAfter(TimeSpan.FromSeconds(5));
+            
+            var scopeObjects = ((TestKestrelTrace)_frameConnectionContext.ServiceContext.Log)
+                                    .Logger
+                                    .Scopes
+                                    .OfType<IReadOnlyList<KeyValuePair<string, object>>>()
+                                    .ToList();
+
+            Assert.Equal(1, scopeObjects.Count);
+            var pairs = scopeObjects[0].ToDictionary(p => p.Key, p => p.Value);
+            Assert.True(pairs.ContainsKey("ConnectionId"));
+            Assert.Equal(_frameConnection.ConnectionId, pairs["ConnectionId"]);
+        }
     }
 }

test/shared/TestApplicationErrorLogger.cs

@@ -19,6 +19,8 @@ namespace Microsoft.AspNetCore.Testing
 
         public ConcurrentBag<LogMessage> Messages { get; } = new ConcurrentBag<LogMessage>();
 
+        public ConcurrentBag<object> Scopes { get; } = new ConcurrentBag<object>();
+
         public int TotalErrorsLogged => Messages.Count(message => message.LogLevel == LogLevel.Error);
 
         public int CriticalErrorsLogged => Messages.Count(message => message.LogLevel == LogLevel.Critical);
@@ -27,6 +29,7 @@ namespace Microsoft.AspNetCore.Testing
 
         public IDisposable BeginScope<TState>(TState state)
         {
+            Scopes.Add(state);
             return new Disposable(() => { });
         }
 

test/shared/TestServiceContext.cs

@@ -13,8 +13,12 @@ namespace Microsoft.AspNetCore.Testing
     public class TestServiceContext : ServiceContext
     {
         public TestServiceContext()
-            : this(new LoggerFactory(new[] { new KestrelTestLoggerProvider() }))
         {
+            var logger = new TestApplicationErrorLogger();
+            var kestrelTrace = new TestKestrelTrace(logger);
+            var loggerFactory = new LoggerFactory(new[] { new KestrelTestLoggerProvider(logger) });
+
+            Initialize(loggerFactory, kestrelTrace);
         }
 
         public TestServiceContext(ILoggerFactory loggerFactory)
@@ -23,6 +27,11 @@ namespace Microsoft.AspNetCore.Testing
         }
 
         public TestServiceContext(ILoggerFactory loggerFactory, IKestrelTrace kestrelTrace)
+        {
+            Initialize(loggerFactory, kestrelTrace);
+        }
+
+        private void Initialize(ILoggerFactory loggerFactory, IKestrelTrace kestrelTrace)
         {
             LoggerFactory = loggerFactory;
             Log = kestrelTrace;
@@ -37,7 +46,7 @@ namespace Microsoft.AspNetCore.Testing
             };
         }
 
-        public ILoggerFactory LoggerFactory { get; }
+        public ILoggerFactory LoggerFactory { get; set; }
 
         public string DateHeaderValue => DateHeaderValueManager.GetDateHeaderValues().String;
     }