From 7ebbdad9746f21b5966c62d68717fa68e21df72d Mon Sep 17 00:00:00 2001 From: David Fowler Date: Wed, 12 Jul 2017 11:45:08 -0700 Subject: [PATCH] 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 --- .../Internal/ConnectionLogScope.cs | 63 +++++++++ .../Internal/FrameConnection.cs | 123 ++++++++++-------- .../FrameConnectionTests.cs | 22 ++++ test/shared/TestApplicationErrorLogger.cs | 3 + test/shared/TestServiceContext.cs | 13 +- 5 files changed, 168 insertions(+), 56 deletions(-) create mode 100644 src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/ConnectionLogScope.cs diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/ConnectionLogScope.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/ConnectionLogScope.cs new file mode 100644 index 0000000000..3d1b882e82 --- /dev/null +++ b/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> + { + private readonly string _connectionId; + + private string _cachedToString; + + public ConnectionLogScope(string connectionId) + { + _connectionId = connectionId; + } + + public KeyValuePair this[int index] + { + get + { + if (index == 0) + { + return new KeyValuePair("ConnectionId", _connectionId); + } + + throw new ArgumentOutOfRangeException(nameof(index)); + } + } + + public int Count => 1; + + public IEnumerator> 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; + } + } +} diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs index 1574d3bf7e..85b754ce9c 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs +++ b/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(IHttpApplication application) { - _lifetimeTask = ProcessRequestsAsync(application); + _lifetimeTask = ProcessRequestsAsync(application); } private async Task ProcessRequestsAsync(IHttpApplication application) { - try + using (BeginConnectionScope()) { - Log.ConnectionStart(ConnectionId); - 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) + try { - adaptedPipeline = new AdaptedPipeline(input, - output, - PipeFactory.Create(AdaptedInputPipeOptions), - PipeFactory.Create(AdaptedOutputPipeOptions), - Log); + Log.ConnectionStart(ConnectionId); + KestrelEventSource.Log.ConnectionStart(this, _context.ConnectionInformation); - input = adaptedPipeline.Input.Reader; - output = adaptedPipeline.Output; + 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, + 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; } - - // _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) + catch (Exception ex) { - // Stream can be null here and run async will close the connection in that case - var stream = await ApplyConnectionAdaptersAsync(); - adaptedPipelineTask = adaptedPipeline.RunAsync(stream); + Log.LogError(0, ex, $"Unexpected exception in {nameof(FrameConnection)}.{nameof(ProcessRequestsAsync)}."); } - - 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) + finally { - _context.ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne(); - } - else - { - _context.ServiceContext.ConnectionManager.NormalConnectionCount.ReleaseOne(); - } + _context.ServiceContext.ConnectionManager.RemoveConnection(_context.FrameConnectionId); + DisposeAdaptedConnections(); - Log.ConnectionStop(ConnectionId); - KestrelEventSource.Log.ConnectionStop(this); + if (_frame.WasUpgraded) + { + _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; + } } } diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.Core.Tests/FrameConnectionTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.Core.Tests/FrameConnectionTests.cs index 8c1d74eb24..faa662f899 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.Core.Tests/FrameConnectionTests.cs +++ b/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>>() + .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"]); + } } } diff --git a/test/shared/TestApplicationErrorLogger.cs b/test/shared/TestApplicationErrorLogger.cs index 63f710cd7d..936624f1a8 100644 --- a/test/shared/TestApplicationErrorLogger.cs +++ b/test/shared/TestApplicationErrorLogger.cs @@ -19,6 +19,8 @@ namespace Microsoft.AspNetCore.Testing public ConcurrentBag Messages { get; } = new ConcurrentBag(); + public ConcurrentBag Scopes { get; } = new ConcurrentBag(); + 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 state) { + Scopes.Add(state); return new Disposable(() => { }); } diff --git a/test/shared/TestServiceContext.cs b/test/shared/TestServiceContext.cs index 2d9b772e43..61487222d7 100644 --- a/test/shared/TestServiceContext.cs +++ b/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; }