From e4350945c56d69523fe36bf33c58b955db3d8985 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Tue, 11 Jul 2017 10:03:15 -0700 Subject: [PATCH] Attach the correlation id to the request scope if logging is on (#1138) - Add the correlation id to the request scope as well as setting it as the parent id of the activity --- .../Internal/HostingApplicationDiagnostics.cs | 24 +++++++--- .../Internal/HostingLoggerExtensions.cs | 18 ++++--- .../HostingApplicationTests.cs | 48 +++++++++++++++++-- 3 files changed, 74 insertions(+), 16 deletions(-) diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplicationDiagnostics.cs b/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplicationDiagnostics.cs index 50d29efd5e..d485b1a060 100644 --- a/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplicationDiagnostics.cs +++ b/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplicationDiagnostics.cs @@ -46,12 +46,22 @@ namespace Microsoft.AspNetCore.Hosting.Internal RecordRequestStartEventLog(httpContext); } + var diagnosticListenerEnabled = _diagnosticListener.IsEnabled(); + var loggingEnabled = _logger.IsEnabled(LogLevel.Critical); - if (_diagnosticListener.IsEnabled()) + // If logging is enabled or the diagnostic listener is enabled, try to get the correlation + // id from the header + StringValues correlationId; + if (diagnosticListenerEnabled || loggingEnabled) + { + httpContext.Request.Headers.TryGetValue(RequestIdHeaderName, out correlationId); + } + + if (diagnosticListenerEnabled) { if (_diagnosticListener.IsEnabled(ActivityName, httpContext)) { - context.Activity = StartActivity(httpContext); + context.Activity = StartActivity(httpContext, correlationId); } if (_diagnosticListener.IsEnabled(DeprecatedDiagnosticsBeginRequestKey)) { @@ -61,12 +71,12 @@ namespace Microsoft.AspNetCore.Hosting.Internal } // To avoid allocation, return a null scope if the logger is not on at least to some degree. - if (_logger.IsEnabled(LogLevel.Critical)) + if (loggingEnabled) { // Scope may be relevant for a different level of logging, so we always create it // see: https://github.com/aspnet/Hosting/pull/944 // Scope can be null if logging is not on. - context.Scope = _logger.RequestScope(httpContext); + context.Scope = _logger.RequestScope(httpContext, correlationId); if (_logger.IsEnabled(LogLevel.Information)) { @@ -230,15 +240,15 @@ namespace Microsoft.AspNetCore.Hosting.Internal } [MethodImpl(MethodImplOptions.NoInlining)] - private Activity StartActivity(HttpContext httpContext) + private Activity StartActivity(HttpContext httpContext, StringValues requestId) { var activity = new Activity(ActivityName); - if (httpContext.Request.Headers.TryGetValue(RequestIdHeaderName, out var requestId)) + if (!StringValues.IsNullOrEmpty(requestId)) { activity.SetParentId(requestId); // We expect baggage to be empty by default - // Only very advanced users will be using it in near future, we encouradge them to keep baggage small (few items) + // Only very advanced users will be using it in near future, we encourage them to keep baggage small (few items) string[] baggage = httpContext.Request.Headers.GetCommaSeparatedValues(CorrelationContextHeaderName); if (baggage != StringValues.Empty) { diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs b/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs index 987924d8e6..a0579880a0 100644 --- a/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs @@ -13,10 +13,9 @@ namespace Microsoft.AspNetCore.Hosting.Internal { internal static class HostingLoggerExtensions { - public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext) + public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext, string correlationId) { - - return logger.BeginScope(new HostingLogScope(httpContext)); + return logger.BeginScope(new HostingLogScope(httpContext, correlationId)); } public static void ApplicationError(this ILogger logger, Exception exception) @@ -96,6 +95,7 @@ namespace Microsoft.AspNetCore.Hosting.Internal private class HostingLogScope : IReadOnlyList> { private readonly HttpContext _httpContext; + private readonly string _correlationId; private string _cachedToString; @@ -103,7 +103,7 @@ namespace Microsoft.AspNetCore.Hosting.Internal { get { - return 2; + return 3; } } @@ -119,13 +119,19 @@ namespace Microsoft.AspNetCore.Hosting.Internal { return new KeyValuePair("RequestPath", _httpContext.Request.Path.ToString()); } - throw new IndexOutOfRangeException(nameof(index)); + else if (index == 2) + { + return new KeyValuePair("CorrelationId", _correlationId); + } + + throw new ArgumentOutOfRangeException(nameof(index)); } } - public HostingLogScope(HttpContext httpContext) + public HostingLogScope(HttpContext httpContext, string correlationId) { _httpContext = httpContext; + _correlationId = correlationId; } public override string ToString() diff --git a/test/Microsoft.AspNetCore.Hosting.Tests/HostingApplicationTests.cs b/test/Microsoft.AspNetCore.Hosting.Tests/HostingApplicationTests.cs index e75ebbe778..fcecc5e0aa 100644 --- a/test/Microsoft.AspNetCore.Hosting.Tests/HostingApplicationTests.cs +++ b/test/Microsoft.AspNetCore.Hosting.Tests/HostingApplicationTests.cs @@ -4,6 +4,7 @@ using System; using System.Collections.Generic; using System.Diagnostics; +using System.Linq; using System.Reflection; using System.Threading.Tasks; using Microsoft.AspNetCore.Hosting.Internal; @@ -30,6 +31,22 @@ namespace Microsoft.AspNetCore.Hosting.Tests hostingApplication.DisposeContext(context, null); } + [Fact] + public void CreateContextSetsCorrelationIdInScope() + { + // Arrange + var logger = new LoggerWithScopes(); + var hostingApplication = CreateApplication(out var features, logger: logger); + features.Get().Headers["Request-Id"] = "some correlation id"; + + // Act + var context = hostingApplication.CreateContext(features); + + Assert.Equal(1, logger.Scopes.Count); + var pairs = ((IReadOnlyList>)logger.Scopes[0]).ToDictionary(p => p.Key, p => p.Value); + Assert.Equal("some correlation id", pairs["CorrelationId"].ToString()); + } + [Fact] public void ActivityIsNotCreatedWhenIsEnabledForActivityIsFalse() { @@ -60,7 +77,7 @@ namespace Microsoft.AspNetCore.Hosting.Tests hostingApplication.CreateContext(features); Assert.Null(Activity.Current); Assert.True(isEnabledActivityFired); - Assert.False (isEnabledStartFired); + Assert.False(isEnabledStartFired); Assert.False(eventsFired); } @@ -261,7 +278,7 @@ namespace Microsoft.AspNetCore.Hosting.Tests } private static HostingApplication CreateApplication(out FeatureCollection features, - DiagnosticListener diagnosticSource = null) + DiagnosticListener diagnosticSource = null, ILogger logger = null) { var httpContextFactory = new Mock(); @@ -272,7 +289,7 @@ namespace Microsoft.AspNetCore.Hosting.Tests var hostingApplication = new HostingApplication( ctx => Task.FromResult(0), - new NullScopeLogger(), + logger ?? new NullScopeLogger(), diagnosticSource ?? new NoopDiagnosticSource(), httpContextFactory.Object); @@ -290,6 +307,31 @@ namespace Microsoft.AspNetCore.Hosting.Tests } } + private class LoggerWithScopes : ILogger + { + public IDisposable BeginScope(TState state) + { + Scopes.Add(state); + return new Scope(); + } + + public List Scopes { get; set; } = new List(); + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + + } + + private class Scope : IDisposable + { + public void Dispose() + { + } + } + } + private class NoopDiagnosticSource : DiagnosticListener { public NoopDiagnosticSource() : base("DummyListener")