From dc9ed604651e4da99592ba2ccb1c976255c04af3 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Tue, 22 Aug 2017 14:32:58 -0700 Subject: [PATCH] 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. --- .../Internal/ConnectionHandler.cs | 27 ++- src/Kestrel.Core/Internal/FrameConnection.cs | 163 ++++++++---------- .../ConnectionHandlerTests.cs | 70 ++++++++ .../FrameConnectionTests.cs | 24 --- 4 files changed, 167 insertions(+), 117 deletions(-) create mode 100644 test/Kestrel.Core.Tests/ConnectionHandlerTests.cs diff --git a/src/Kestrel.Core/Internal/ConnectionHandler.cs b/src/Kestrel.Core/Internal/ConnectionHandler.cs index d94de12429..5e3513b5ac 100644 --- a/src/Kestrel.Core/Internal/ConnectionHandler.cs +++ b/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 diff --git a/src/Kestrel.Core/Internal/FrameConnection.cs b/src/Kestrel.Core/Internal/FrameConnection.cs index f11c6102a1..f2e3a3e172 100644 --- a/src/Kestrel.Core/Internal/FrameConnection.cs +++ b/src/Kestrel.Core/Internal/FrameConnection.cs @@ -92,92 +92,87 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal private async Task ProcessRequestsAsync(IHttpApplication 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); - KestrelEventSource.Log.ConnectionStart(this); + adaptedPipeline = new AdaptedPipeline(transport, + application, + PipeFactory.Create(AdaptedInputPipeOptions), + PipeFactory.Create(AdaptedOutputPipeOptions)); - AdaptedPipeline adaptedPipeline = null; - 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()?.ApplicationProtocol == "h2" && - Interlocked.CompareExchange(ref _http2ConnectionState, Http2ConnectionStarted, Http2ConnectionNotStarted) == Http2ConnectionNotStarted) - { - await _http2Connection.ProcessAsync(httpApplication); - } - else - { - await _frame.ProcessRequestsAsync(); - } - - await adaptedPipelineTask; - await _socketClosedTcs.Task; + transport = adaptedPipeline; } - 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)}."); - } - finally + 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) { - _context.ServiceContext.ConnectionManager.RemoveConnection(_context.FrameConnectionId); - DisposeAdaptedConnections(); - - if (_frame.WasUpgraded) - { - _context.ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne(); - } - else - { - _context.ServiceContext.ConnectionManager.NormalConnectionCount.ReleaseOne(); - } - - Log.ConnectionStop(ConnectionId); - KestrelEventSource.Log.ConnectionStop(this); + // 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()?.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; - } } } diff --git a/test/Kestrel.Core.Tests/ConnectionHandlerTests.cs b/test/Kestrel.Core.Tests/ConnectionHandlerTests.cs new file mode 100644 index 0000000000..b21387675e --- /dev/null +++ b/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(); + 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>>() + .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(this); + Set(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; } + } + } +} diff --git a/test/Kestrel.Core.Tests/FrameConnectionTests.cs b/test/Kestrel.Core.Tests/FrameConnectionTests.cs index e77de9b870..b2418bf61a 100644 --- a/test/Kestrel.Core.Tests/FrameConnectionTests.cs +++ b/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>>() - .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); - } } }