From 1376b682dc8525c96e8d29a2b3a12805a8371325 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Fri, 14 Jun 2019 00:55:31 -0700 Subject: [PATCH 1/6] Hoist activity fields to the logging scope - Expose SpanId, TraceId and ParentId to logging scope properties - Added tests to verify the Hierarchical ID format --- .../Internal/HostingApplicationDiagnostics.cs | 2 +- .../src/Internal/HostingLoggerExtensions.cs | 43 ++++++++++++++---- .../Hosting/test/HostingApplicationTests.cs | 45 +++++++++++++++---- 3 files changed, 71 insertions(+), 19 deletions(-) diff --git a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs index b983aa397dbc..c278a867784e 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs @@ -68,7 +68,7 @@ public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context // 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.Activity.Id); + context.Scope = _logger.RequestScope(httpContext, context.Activity); if (_logger.IsEnabled(LogLevel.Information)) { diff --git a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs index 48e5db98183a..0e2fe82f6311 100644 --- a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs +++ b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs @@ -4,6 +4,7 @@ using System; using System.Collections; using System.Collections.Generic; +using System.Diagnostics; using System.Globalization; using System.Reflection; using Microsoft.AspNetCore.Http; @@ -13,9 +14,9 @@ namespace Microsoft.AspNetCore.Hosting.Internal { internal static class HostingLoggerExtensions { - public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext, string activityId) + public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext, Activity activity) { - return logger.BeginScope(new HostingLogScope(httpContext, activityId)); + return logger.BeginScope(new HostingLogScope(httpContext, activity)); } public static void ApplicationError(this ILogger logger, Exception exception) @@ -96,7 +97,9 @@ private class HostingLogScope : IReadOnlyList> { private readonly string _path; private readonly string _traceIdentifier; - private readonly string _activityId; + private readonly string _traceId; + private readonly string _parentId; + private readonly string _spanId; private string _cachedToString; @@ -104,7 +107,7 @@ public int Count { get { - return 3; + return 5; } } @@ -122,20 +125,40 @@ public KeyValuePair this[int index] } else if (index == 2) { - return new KeyValuePair("ActivityId", _activityId); + return new KeyValuePair("SpanId", _spanId); + } + else if (index == 3) + { + return new KeyValuePair("TraceId", _traceId); + } + else if (index == 4) + { + return new KeyValuePair("ParentId", _parentId); } throw new ArgumentOutOfRangeException(nameof(index)); } } - public HostingLogScope(HttpContext httpContext, string activityId) + public HostingLogScope(HttpContext httpContext, Activity activity) { _traceIdentifier = httpContext.TraceIdentifier; _path = (httpContext.Request.PathBase.HasValue ? httpContext.Request.PathBase + httpContext.Request.Path : httpContext.Request.Path).ToString(); - _activityId = activityId; + + if (activity.IdFormat == ActivityIdFormat.W3C) + { + _traceId = activity.TraceId.ToHexString(); + _spanId = activity.SpanId.ToHexString(); + _parentId = activity.ParentId; + } + else + { + _traceId = activity.RootId; + _spanId = activity.Id; + _parentId = activity.ParentId; + } } public override string ToString() @@ -144,10 +167,12 @@ public override string ToString() { _cachedToString = string.Format( CultureInfo.InvariantCulture, - "RequestPath:{0} RequestId:{1}, ActivityId:{2}", + "RequestPath:{0} RequestId:{1}, SpanId:{2}, TraceId:{3}, ParentId:{4}", _path, _traceIdentifier, - _activityId); + _spanId, + _traceId, + _parentId); } return _cachedToString; diff --git a/src/Hosting/Hosting/test/HostingApplicationTests.cs b/src/Hosting/Hosting/test/HostingApplicationTests.cs index 7454d738ef73..1b8a9c1ef022 100644 --- a/src/Hosting/Hosting/test/HostingApplicationTests.cs +++ b/src/Hosting/Hosting/test/HostingApplicationTests.cs @@ -42,7 +42,7 @@ public void CreateContextWithDisabledLoggerDoesNotCreateActivity() } [Fact] - public void CreateContextWithEnabledLoggerCreatesActivityAndSetsActivityIdInScope() + public void CreateContextWithEnabledLoggerCreatesActivityAndSetsActivityInScope() { // Arrange var logger = new LoggerWithScopes(isEnabled: true); @@ -53,7 +53,36 @@ public void CreateContextWithEnabledLoggerCreatesActivityAndSetsActivityIdInScop Assert.Single(logger.Scopes); var pairs = ((IReadOnlyList>)logger.Scopes[0]).ToDictionary(p => p.Key, p => p.Value); - Assert.Equal(Activity.Current.Id, pairs["ActivityId"].ToString()); + Assert.Equal(Activity.Current.Id, pairs["SpanId"].ToString()); + Assert.Equal(Activity.Current.RootId, pairs["TraceId"].ToString()); + Assert.Null(pairs["ParentId"]?.ToString()); + } + + [Fact] + public void CreateContextWithEnabledLoggerAndRequestIdCreatesActivityAndSetsActivityInScope() + { + // Arrange + + // Generate an id we can use for the request id header (in the correct format) + var activity = new Activity("IncomingRequest"); + activity.Start(); + var id = activity.Id; + activity.Stop(); + + var logger = new LoggerWithScopes(isEnabled: true); + var hostingApplication = CreateApplication(out var features, logger: logger, configure: context => + { + context.Request.Headers["Request-Id"] = id; + }); + + // Act + var context = hostingApplication.CreateContext(features); + + Assert.Single(logger.Scopes); + var pairs = ((IReadOnlyList>)logger.Scopes[0]).ToDictionary(p => p.Key, p => p.Value); + Assert.Equal(Activity.Current.Id, pairs["SpanId"].ToString()); + Assert.Equal(Activity.Current.RootId, pairs["TraceId"].ToString()); + Assert.Equal(id, pairs["ParentId"].ToString()); } [Fact] @@ -90,10 +119,6 @@ public void ActivityStopDoesNotFireIfNoListenerAttachedForStart() // Act var context = hostingApplication.CreateContext(features); - Assert.Single(logger.Scopes); - var pairs = ((IReadOnlyList>)logger.Scopes[0]).ToDictionary(p => p.Key, p => p.Value); - Assert.Equal(Activity.Current.Id, pairs["ActivityId"].ToString()); - hostingApplication.DisposeContext(context, exception: null); Assert.False(startFired); @@ -398,13 +423,15 @@ private static void AssertProperty(object o, string name) } private static HostingApplication CreateApplication(out FeatureCollection features, - DiagnosticListener diagnosticSource = null, ILogger logger = null) + DiagnosticListener diagnosticSource = null, ILogger logger = null, Action configure = null) { var httpContextFactory = new Mock(); features = new FeatureCollection(); features.Set(new HttpRequestFeature()); - httpContextFactory.Setup(s => s.Create(It.IsAny())).Returns(new DefaultHttpContext(features)); + var context = new DefaultHttpContext(features); + configure?.Invoke(context); + httpContextFactory.Setup(s => s.Create(It.IsAny())).Returns(context); httpContextFactory.Setup(s => s.Dispose(It.IsAny())); var hostingApplication = new HostingApplication( @@ -453,7 +480,7 @@ public IDisposable BeginScope(TState state) public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { - + } private class Scope : IDisposable From ed26c78aee3bafe71a8db873547b1bd8086ec8c3 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Fri, 14 Jun 2019 11:41:10 -0700 Subject: [PATCH 2/6] Update src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs Co-Authored-By: Liudmila Molkova --- src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs index 0e2fe82f6311..bf3de0c976b1 100644 --- a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs +++ b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs @@ -151,7 +151,7 @@ public HostingLogScope(HttpContext httpContext, Activity activity) { _traceId = activity.TraceId.ToHexString(); _spanId = activity.SpanId.ToHexString(); - _parentId = activity.ParentId; + _parentId = activity.ParentSpanId.ToHexString(); } else { From 59461ed025ed67893d3d9c1cc46e4f8a76a45a12 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 15 Jun 2019 02:29:50 -0700 Subject: [PATCH 3/6] Store the activity and lazily compute the various properties --- .../src/Internal/ActivityExtensions.cs | 43 +++++++++++++++++++ .../src/Internal/HostingLoggerExtensions.cs | 29 ++++--------- 2 files changed, 51 insertions(+), 21 deletions(-) create mode 100644 src/Hosting/Hosting/src/Internal/ActivityExtensions.cs diff --git a/src/Hosting/Hosting/src/Internal/ActivityExtensions.cs b/src/Hosting/Hosting/src/Internal/ActivityExtensions.cs new file mode 100644 index 000000000000..6c943f4030a4 --- /dev/null +++ b/src/Hosting/Hosting/src/Internal/ActivityExtensions.cs @@ -0,0 +1,43 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Text; + +namespace Microsoft.AspNetCore.Hosting.Internal +{ + /// + /// Helpers for getting the right values from Activity no matter the format (w3c or hierarchical) + /// + internal static class ActivityExtensions + { + public static string GetSpanId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.Id, + ActivityIdFormat.W3C => activity.SpanId.ToHexString(), + _ => null, + }; + } + + public static string GetTraceId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.RootId, + ActivityIdFormat.W3C => activity.TraceId.ToHexString(), + _ => null, + }; + } + + public static string GetParentId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.ParentId, + ActivityIdFormat.W3C => activity.ParentSpanId.ToHexString(), + _ => null, + }; + } + } +} diff --git a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs index bf3de0c976b1..72140480ab39 100644 --- a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs +++ b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs @@ -97,9 +97,7 @@ private class HostingLogScope : IReadOnlyList> { private readonly string _path; private readonly string _traceIdentifier; - private readonly string _traceId; - private readonly string _parentId; - private readonly string _spanId; + private readonly Activity _activity; private string _cachedToString; @@ -125,15 +123,15 @@ public KeyValuePair this[int index] } else if (index == 2) { - return new KeyValuePair("SpanId", _spanId); + return new KeyValuePair("SpanId", _activity.GetSpanId()); } else if (index == 3) { - return new KeyValuePair("TraceId", _traceId); + return new KeyValuePair("TraceId", _activity.GetTraceId()); } else if (index == 4) { - return new KeyValuePair("ParentId", _parentId); + return new KeyValuePair("ParentId", _activity.GetParentId()); } throw new ArgumentOutOfRangeException(nameof(index)); @@ -147,18 +145,7 @@ public HostingLogScope(HttpContext httpContext, Activity activity) ? httpContext.Request.PathBase + httpContext.Request.Path : httpContext.Request.Path).ToString(); - if (activity.IdFormat == ActivityIdFormat.W3C) - { - _traceId = activity.TraceId.ToHexString(); - _spanId = activity.SpanId.ToHexString(); - _parentId = activity.ParentSpanId.ToHexString(); - } - else - { - _traceId = activity.RootId; - _spanId = activity.Id; - _parentId = activity.ParentId; - } + _activity = activity; } public override string ToString() @@ -170,9 +157,9 @@ public override string ToString() "RequestPath:{0} RequestId:{1}, SpanId:{2}, TraceId:{3}, ParentId:{4}", _path, _traceIdentifier, - _spanId, - _traceId, - _parentId); + _activity.GetSpanId(), + _activity.GetTraceId(), + _activity.GetParentId()); } return _cachedToString; From 4a93b689dc2e6e945d16c8d5695fbed9dd341835 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 15 Jun 2019 03:46:19 -0700 Subject: [PATCH 4/6] Temporarily work around bug in EventLogLogger --- src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs index 72140480ab39..b09319cbe26a 100644 --- a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs +++ b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs @@ -123,15 +123,15 @@ public KeyValuePair this[int index] } else if (index == 2) { - return new KeyValuePair("SpanId", _activity.GetSpanId()); + return new KeyValuePair("SpanId", _activity.GetSpanId() ?? string.Empty); } else if (index == 3) { - return new KeyValuePair("TraceId", _activity.GetTraceId()); + return new KeyValuePair("TraceId", _activity.GetTraceId() ?? string.Empty); } else if (index == 4) { - return new KeyValuePair("ParentId", _activity.GetParentId()); + return new KeyValuePair("ParentId", _activity.GetParentId() ?? string.Empty); } throw new ArgumentOutOfRangeException(nameof(index)); From 5efa3fe7b7ca6ec09f1f67f2b187df8600dc24bf Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 15 Jun 2019 08:40:56 -0700 Subject: [PATCH 5/6] Fixed test --- src/Hosting/Hosting/test/HostingApplicationTests.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Hosting/Hosting/test/HostingApplicationTests.cs b/src/Hosting/Hosting/test/HostingApplicationTests.cs index 1b8a9c1ef022..d799d984da46 100644 --- a/src/Hosting/Hosting/test/HostingApplicationTests.cs +++ b/src/Hosting/Hosting/test/HostingApplicationTests.cs @@ -55,7 +55,7 @@ public void CreateContextWithEnabledLoggerCreatesActivityAndSetsActivityInScope( var pairs = ((IReadOnlyList>)logger.Scopes[0]).ToDictionary(p => p.Key, p => p.Value); Assert.Equal(Activity.Current.Id, pairs["SpanId"].ToString()); Assert.Equal(Activity.Current.RootId, pairs["TraceId"].ToString()); - Assert.Null(pairs["ParentId"]?.ToString()); + Assert.Equal(string.Empty, pairs["ParentId"]?.ToString()); } [Fact] From 9d2b9e92c68b61e12f41b33efee57bf561e023c4 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 15 Jun 2019 10:46:51 -0700 Subject: [PATCH 6/6] Change where the null colaese happens --- src/Hosting/Hosting/src/Internal/ActivityExtensions.cs | 6 +++--- src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs | 6 +++--- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/src/Hosting/Hosting/src/Internal/ActivityExtensions.cs b/src/Hosting/Hosting/src/Internal/ActivityExtensions.cs index 6c943f4030a4..0391346cf97b 100644 --- a/src/Hosting/Hosting/src/Internal/ActivityExtensions.cs +++ b/src/Hosting/Hosting/src/Internal/ActivityExtensions.cs @@ -17,7 +17,7 @@ public static string GetSpanId(this Activity activity) ActivityIdFormat.Hierarchical => activity.Id, ActivityIdFormat.W3C => activity.SpanId.ToHexString(), _ => null, - }; + } ?? string.Empty; } public static string GetTraceId(this Activity activity) @@ -27,7 +27,7 @@ public static string GetTraceId(this Activity activity) ActivityIdFormat.Hierarchical => activity.RootId, ActivityIdFormat.W3C => activity.TraceId.ToHexString(), _ => null, - }; + } ?? string.Empty; } public static string GetParentId(this Activity activity) @@ -37,7 +37,7 @@ public static string GetParentId(this Activity activity) ActivityIdFormat.Hierarchical => activity.ParentId, ActivityIdFormat.W3C => activity.ParentSpanId.ToHexString(), _ => null, - }; + } ?? string.Empty; } } } diff --git a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs index b09319cbe26a..72140480ab39 100644 --- a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs +++ b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs @@ -123,15 +123,15 @@ public KeyValuePair this[int index] } else if (index == 2) { - return new KeyValuePair("SpanId", _activity.GetSpanId() ?? string.Empty); + return new KeyValuePair("SpanId", _activity.GetSpanId()); } else if (index == 3) { - return new KeyValuePair("TraceId", _activity.GetTraceId() ?? string.Empty); + return new KeyValuePair("TraceId", _activity.GetTraceId()); } else if (index == 4) { - return new KeyValuePair("ParentId", _activity.GetParentId() ?? string.Empty); + return new KeyValuePair("ParentId", _activity.GetParentId()); } throw new ArgumentOutOfRangeException(nameof(index));