Skip to content

Commit

Permalink
Hoist activity fields to the logging scope (#11211)
Browse files Browse the repository at this point in the history
- Expose SpanId, TraceId and ParentId to logging scope properties
- Added tests to verify the Hierarchical ID format
- Store the activity and lazily compute the various properties
  • Loading branch information
davidfowl authored Jun 17, 2019
1 parent 4235dd2 commit f7a2d3c
Show file tree
Hide file tree
Showing 4 changed files with 101 additions and 19 deletions.
43 changes: 43 additions & 0 deletions src/Hosting/Hosting/src/Internal/ActivityExtensions.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,43 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Text;

namespace Microsoft.AspNetCore.Hosting.Internal
{
/// <summary>
/// Helpers for getting the right values from Activity no matter the format (w3c or hierarchical)
/// </summary>
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,
} ?? string.Empty;
}

public static string GetTraceId(this Activity activity)
{
return activity.IdFormat switch
{
ActivityIdFormat.Hierarchical => activity.RootId,
ActivityIdFormat.W3C => activity.TraceId.ToHexString(),
_ => null,
} ?? string.Empty;
}

public static string GetParentId(this Activity activity)
{
return activity.IdFormat switch
{
ActivityIdFormat.Hierarchical => activity.ParentId,
ActivityIdFormat.W3C => activity.ParentSpanId.ToHexString(),
_ => null,
} ?? string.Empty;
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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))
{
Expand Down
30 changes: 21 additions & 9 deletions src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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)
Expand Down Expand Up @@ -96,15 +97,15 @@ private class HostingLogScope : IReadOnlyList<KeyValuePair<string, object>>
{
private readonly string _path;
private readonly string _traceIdentifier;
private readonly string _activityId;
private readonly Activity _activity;

private string _cachedToString;

public int Count
{
get
{
return 3;
return 5;
}
}

Expand All @@ -122,20 +123,29 @@ public KeyValuePair<string, object> this[int index]
}
else if (index == 2)
{
return new KeyValuePair<string, object>("ActivityId", _activityId);
return new KeyValuePair<string, object>("SpanId", _activity.GetSpanId());
}
else if (index == 3)
{
return new KeyValuePair<string, object>("TraceId", _activity.GetTraceId());
}
else if (index == 4)
{
return new KeyValuePair<string, object>("ParentId", _activity.GetParentId());
}

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;

_activity = activity;
}

public override string ToString()
Expand All @@ -144,10 +154,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);
_activity.GetSpanId(),
_activity.GetTraceId(),
_activity.GetParentId());
}

return _cachedToString;
Expand Down
45 changes: 36 additions & 9 deletions src/Hosting/Hosting/test/HostingApplicationTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,7 @@ public void CreateContextWithDisabledLoggerDoesNotCreateActivity()
}

[Fact]
public void CreateContextWithEnabledLoggerCreatesActivityAndSetsActivityIdInScope()
public void CreateContextWithEnabledLoggerCreatesActivityAndSetsActivityInScope()
{
// Arrange
var logger = new LoggerWithScopes(isEnabled: true);
Expand All @@ -53,7 +53,36 @@ public void CreateContextWithEnabledLoggerCreatesActivityAndSetsActivityIdInScop

Assert.Single(logger.Scopes);
var pairs = ((IReadOnlyList<KeyValuePair<string, object>>)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.Equal(string.Empty, 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<KeyValuePair<string, object>>)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]
Expand Down Expand Up @@ -90,10 +119,6 @@ public void ActivityStopDoesNotFireIfNoListenerAttachedForStart()
// Act
var context = hostingApplication.CreateContext(features);

Assert.Single(logger.Scopes);
var pairs = ((IReadOnlyList<KeyValuePair<string, object>>)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);
Expand Down Expand Up @@ -398,13 +423,15 @@ private static void AssertProperty<T>(object o, string name)
}

private static HostingApplication CreateApplication(out FeatureCollection features,
DiagnosticListener diagnosticSource = null, ILogger logger = null)
DiagnosticListener diagnosticSource = null, ILogger logger = null, Action<DefaultHttpContext> configure = null)
{
var httpContextFactory = new Mock<IHttpContextFactory>();

features = new FeatureCollection();
features.Set<IHttpRequestFeature>(new HttpRequestFeature());
httpContextFactory.Setup(s => s.Create(It.IsAny<IFeatureCollection>())).Returns(new DefaultHttpContext(features));
var context = new DefaultHttpContext(features);
configure?.Invoke(context);
httpContextFactory.Setup(s => s.Create(It.IsAny<IFeatureCollection>())).Returns(context);
httpContextFactory.Setup(s => s.Dispose(It.IsAny<HttpContext>()));

var hostingApplication = new HostingApplication(
Expand Down Expand Up @@ -453,7 +480,7 @@ public IDisposable BeginScope<TState>(TState state)

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{

}

private class Scope : IDisposable
Expand Down

0 comments on commit f7a2d3c

Please sign in to comment.