Skip to content

Create an activity more often than before #9361

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 6 commits into from
Apr 18, 2019
Merged

Create an activity more often than before #9361

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
61099ef
Create an activity more often than before
davidfowl Apr 14, 2019
30f00cc
Revert the rename
davidfowl Apr 14, 2019
fe8cf3a
Add the ActivityId to the ToString for the logging scope
davidfowl Apr 14, 2019
bb1968a
Fixed some tests
davidfowl Apr 16, 2019
f23d856
Fix MVC tests to not check the exact activity value
davidfowl Apr 17, 2019
b582b74
Use a sane name for hosting diagnostics
davidfowl Apr 17, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions src/Hosting/Hosting/src/GenericHost/GenericWebHostedService.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,7 +37,7 @@ public GenericWebHostService(IOptions<GenericWebHostServiceOptions> options,
{
Options = options.Value;
Server = server;
Logger = loggerFactory.CreateLogger<GenericWebHostService>();
Logger = loggerFactory.CreateLogger("Microsoft.AspNetCore.Hosting.Diagnostics");
LifetimeLogger = loggerFactory.CreateLogger("Microsoft.Hosting.Lifetime");
DiagnosticListener = diagnosticListener;
HttpContextFactory = httpContextFactory;
Expand All @@ -49,7 +49,7 @@ public GenericWebHostService(IOptions<GenericWebHostServiceOptions> options,

public GenericWebHostServiceOptions Options { get; }
public IServer Server { get; }
public ILogger<GenericWebHostService> Logger { get; }
public ILogger Logger { get; }
// Only for high level lifetime events
public ILogger LifetimeLogger { get; }
public DiagnosticListener DiagnosticListener { get; }
Expand Down
31 changes: 12 additions & 19 deletions src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -51,13 +51,13 @@ public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context
var diagnosticListenerEnabled = _diagnosticListener.IsEnabled();
var loggingEnabled = _logger.IsEnabled(LogLevel.Critical);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is _logger.IsEnabled(LogLevel.Critical) the right level to create an activity? (As generally it will always be on at critical or above)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In theory, there should always be an activity (I need to run some perf tests to see how this affects the default scenarios). This basically replaces the current request id. The current logic assumes if you're going to log a a scope, then the activity should be created.

We added this but there's kinda a chicken and egg problem as we need to make the activity to be a part of the scope before knowing if the scope if there.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There may also need to be another explicit way to turn it on or off outside logging but that's sorta why this is a draft.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Resetable Activity on the connection using something like: #6895

Currently problematic as Activity doesn't support being cleared.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The server would need to own activity creation in that case. I'm not sure we'll come up with anything reasonable in the 3.0 time frame for #6895. I think coupling it to logging is the best bet mostly because the data is for the logging system and that scenario has a bunch of allocations already (the scope, the messages being logged etc).

Maybe the log level needs to be adjusted to something like information but the category is this internal category (which might be a bit weird).

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

dotnet/extensions#1422

Then something like?

var scope = logger.BeginScope(
    (state) => new HostingLogScope(state.httpContext, state.activityId), 
    (httpContext, activityId));

if (!scope.IsNullScope() || (diagnosticListenerEnabled && _diagnosticListener.IsEnabled(ActivityName, httpContext)))
{
    context.Activity = StartActivity(httpContext);
}

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This only helps when scopes are off. We could just add a DisableActivityCreation to the WebHostOptions if we wanted to remove the allocation in benchmarks.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there anyway to do an inversion? Say for example AppInisights is set to sample 5% of activities rather than 100% is there a way to ask it "will you consume this activity" and create based on that; rather than create it 100% of the time and throw it away unobserved 95% of the time?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes there's a plan to support sampling but this feature needs to work with logging when app insights isn't on so that it's possible to correlate logs without too much setup.

See #9340 for the sampling PR. The activity still needs to be created though (so there's a chicken and egg problem)

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@benaadams we will need an Activity not only to track something, but also to propagate the decision that we decided NOT to track something. So head-based sampling would work across the components.


if (loggingEnabled || (diagnosticListenerEnabled && _diagnosticListener.IsEnabled(ActivityName, httpContext)))
{
context.Activity = StartActivity(httpContext);
}

if (diagnosticListenerEnabled)
{
if (_diagnosticListener.IsEnabled(ActivityName, httpContext))
{
context.Activity = StartActivity(httpContext);
}
if (_diagnosticListener.IsEnabled(DeprecatedDiagnosticsBeginRequestKey))
{
startTimestamp = Stopwatch.GetTimestamp();
Expand All @@ -68,16 +68,10 @@ public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context
// To avoid allocation, return a null scope if the logger is not on at least to some degree.
if (loggingEnabled)
{
// Get the request ID (first try TraceParent header otherwise Request-ID header
if (!httpContext.Request.Headers.TryGetValue(TraceParentHeaderName, out var correlationId))
{
httpContext.Request.Headers.TryGetValue(RequestIdHeaderName, out correlationId);
}

// 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, correlationId);
context.Scope = _logger.RequestScope(httpContext, context.Activity.Id);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@SergeyKanzhelev @lmolkova should we split this out into span id and trace id in the logs?

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is what loggers are typically doing. Like in OpenCensus: https://github.com/census-instrumentation/opencensus-specs/blob/c3fd41b28fed96ceffc8c35af280d74cacea3ab2/trace/LogCorrelation.md#key-names-for-tracing-data or Elastic: elastic/ecs#99


if (_logger.IsEnabled(LogLevel.Information))
{
Expand All @@ -90,7 +84,6 @@ public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context
LogRequestStarting(httpContext);
}
}

context.StartTimestamp = startTimestamp;
}

Expand Down Expand Up @@ -138,13 +131,13 @@ public void RequestEnd(HttpContext httpContext, Exception exception, HostingAppl
}

}
}

var activity = context.Activity;
// Always stop activity if it was started
if (activity != null)
{
StopActivity(httpContext, activity);
}
var activity = context.Activity;
// Always stop activity if it was started
if (activity != null)
{
StopActivity(httpContext, activity);
}

if (context.EventLogEnabled && exception != null)
Expand Down Expand Up @@ -261,7 +254,7 @@ private Activity StartActivity(HttpContext httpContext)
// We expect baggage to be empty by default
// 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)
if (baggage.Length > 0)
{
foreach (var item in baggage)
{
Expand Down
17 changes: 9 additions & 8 deletions src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,9 +13,9 @@ namespace Microsoft.AspNetCore.Hosting.Internal
{
internal static class HostingLoggerExtensions
{
public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext, string correlationId)
public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext, string activityId)
{
return logger.BeginScope(new HostingLogScope(httpContext, correlationId));
return logger.BeginScope(new HostingLogScope(httpContext, activityId));
}

public static void ApplicationError(this ILogger logger, Exception exception)
Expand Down Expand Up @@ -96,7 +96,7 @@ private class HostingLogScope : IReadOnlyList<KeyValuePair<string, object>>
{
private readonly string _path;
private readonly string _traceIdentifier;
private readonly string _correlationId;
private readonly string _activityId;

private string _cachedToString;

Expand All @@ -122,20 +122,20 @@ public KeyValuePair<string, object> this[int index]
}
else if (index == 2)
{
return new KeyValuePair<string, object>("CorrelationId", _correlationId);
return new KeyValuePair<string, object>("ActivityId", _activityId);
}

throw new ArgumentOutOfRangeException(nameof(index));
}
}

public HostingLogScope(HttpContext httpContext, string correlationId)
public HostingLogScope(HttpContext httpContext, string activityId)
{
_traceIdentifier = httpContext.TraceIdentifier;
_path = (httpContext.Request.PathBase.HasValue
? httpContext.Request.PathBase + httpContext.Request.Path
: httpContext.Request.Path).ToString();
_correlationId = correlationId;
_activityId = activityId;
}

public override string ToString()
Expand All @@ -144,9 +144,10 @@ public override string ToString()
{
_cachedToString = string.Format(
CultureInfo.InvariantCulture,
"RequestId:{0} RequestPath:{1}",
"RequestPath:{0} RequestId:{1}, ActivityId:{2}",
_path,
_traceIdentifier,
_path);
_activityId);
}

return _cachedToString;
Expand Down
4 changes: 2 additions & 2 deletions src/Hosting/Hosting/src/Internal/WebHost.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,7 @@ internal class WebHost : IWebHost, IAsyncDisposable

private IServiceProvider _applicationServices;
private ExceptionDispatchInfo _applicationServicesException;
private ILogger<WebHost> _logger;
private ILogger _logger;

private bool _stopped;

Expand Down Expand Up @@ -139,7 +139,7 @@ public void Start()
public virtual async Task StartAsync(CancellationToken cancellationToken = default)
{
HostingEventSource.Log.HostStart();
_logger = _applicationServices.GetRequiredService<ILogger<WebHost>>();
_logger = _applicationServices.GetRequiredService<ILoggerFactory>().CreateLogger("Microsoft.AspNetCore.Hosting.Diagnostics");
_logger.Starting();

var application = BuildApplication();
Expand Down
44 changes: 35 additions & 9 deletions src/Hosting/Hosting/test/HostingApplicationTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -30,19 +30,30 @@ public void DisposeContextDoesNotThrowWhenContextScopeIsNull()
}

[Fact]
public void CreateContextSetsCorrelationIdInScope()
public void CreateContextWithDisabledLoggerDoesNotCreateActivity()
{
// Arrange
var logger = new LoggerWithScopes();
var hostingApplication = CreateApplication(out var features);

// Act
hostingApplication.CreateContext(features);

Assert.Null(Activity.Current);
}

[Fact]
public void CreateContextWithEnabledLoggerCreatesActivityAndSetsActivityIdInScope()
{
// Arrange
var logger = new LoggerWithScopes(isEnabled: true);
var hostingApplication = CreateApplication(out var features, logger: logger);
features.Get<IHttpRequestFeature>().Headers["Request-Id"] = "some correlation 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("some correlation id", pairs["CorrelationId"].ToString());
Assert.Equal(Activity.Current.Id, pairs["ActivityId"].ToString());
}

[Fact]
Expand Down Expand Up @@ -352,7 +363,7 @@ private static HostingApplication CreateApplication(out FeatureCollection featur
httpContextFactory.Setup(s => s.Dispose(It.IsAny<HttpContext>()));

var hostingApplication = new HostingApplication(
ctx => Task.FromResult(0),
ctx => Task.CompletedTask,
logger ?? new NullScopeLogger(),
diagnosticSource ?? new NoopDiagnosticSource(),
httpContextFactory.Object);
Expand All @@ -362,9 +373,15 @@ private static HostingApplication CreateApplication(out FeatureCollection featur

private class NullScopeLogger : ILogger
{
private readonly bool _isEnabled;
public NullScopeLogger(bool isEnabled = false)
{
_isEnabled = isEnabled;
}

public IDisposable BeginScope<TState>(TState state) => null;

public bool IsEnabled(LogLevel logLevel) => true;
public bool IsEnabled(LogLevel logLevel) => _isEnabled;

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
Expand All @@ -373,6 +390,12 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except

private class LoggerWithScopes : ILogger
{
private readonly bool _isEnabled;
public LoggerWithScopes(bool isEnabled = false)
{
_isEnabled = isEnabled;
}

public IDisposable BeginScope<TState>(TState state)
{
Scopes.Add(state);
Expand All @@ -381,7 +404,7 @@ public IDisposable BeginScope<TState>(TState state)

public List<object> Scopes { get; set; } = new List<object>();

public bool IsEnabled(LogLevel logLevel) => true;
public bool IsEnabled(LogLevel logLevel) => _isEnabled;

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
Expand All @@ -398,11 +421,14 @@ public void Dispose()

private class NoopDiagnosticSource : DiagnosticListener
{
public NoopDiagnosticSource() : base("DummyListener")
private readonly bool _isEnabled;

public NoopDiagnosticSource(bool isEnabled = false) : base("DummyListener")
{
_isEnabled = isEnabled;
}

public override bool IsEnabled(string name) => true;
public override bool IsEnabled(string name) => _isEnabled;

public override void Write(string name, object value)
{
Expand Down
4 changes: 2 additions & 2 deletions src/Mvc/test/Mvc.FunctionalTests/ApiBehaviorTest.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -81,7 +81,7 @@ await response.Content.ReadAsStringAsync(),
kvp =>
{
Assert.Equal("traceId", kvp.Key);
Assert.Equal(Activity.Current.Id, kvp.Value);
Assert.NotNull(kvp.Value);
});
}
}
Expand Down Expand Up @@ -290,7 +290,7 @@ public async Task ClientErrorResultFilterExecutesForStatusCodeResults()
kvp =>
{
Assert.Equal("traceId", kvp.Key);
Assert.Equal(Activity.Current.Id, kvp.Value);
Assert.NotNull(kvp.Value);
});
}
}
Expand Down
11 changes: 7 additions & 4 deletions src/Mvc/test/Mvc.FunctionalTests/JsonOutputFormatterTestBase.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@
using FormatterWebSite.Controllers;
using Microsoft.AspNetCore.Hosting;
using Newtonsoft.Json;
using Newtonsoft.Json.Linq;
using Xunit;

namespace Microsoft.AspNetCore.Mvc.FunctionalTests
Expand Down Expand Up @@ -161,15 +162,17 @@ public virtual async Task Formatting_ProblemDetails()
{
using var _ = new ActivityReplacer();

// Arrange
var expected = $"{{\"type\":\"https://tools.ietf.org/html/rfc7231#section-6.5.4\",\"title\":\"Not Found\",\"status\":404,\"traceId\":\"{Activity.Current.Id}\"}}";

// Act
var response = await Client.GetAsync($"/JsonOutputFormatter/{nameof(JsonOutputFormatterController.ProblemDetailsResult)}");

// Assert
await response.AssertStatusCodeAsync(HttpStatusCode.NotFound);
Assert.Equal(expected, await response.Content.ReadAsStringAsync());

var obj = JObject.Parse(await response.Content.ReadAsStringAsync());
Assert.Equal("https://tools.ietf.org/html/rfc7231#section-6.5.4", obj.Value<string>("type"));
Assert.Equal("Not Found", obj.Value<string>("title"));
Assert.Equal("404", obj.Value<string>("status"));
Assert.NotNull(obj.Value<string>("traceId"));
}

[Fact]
Expand Down
34 changes: 16 additions & 18 deletions src/Mvc/test/Mvc.FunctionalTests/XmlDataContractSerializerFormattersWrappingTest.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
using System.Net.Http;
using System.Net.Http.Headers;
using System.Threading.Tasks;
using System.Xml.Linq;
using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.Mvc.Formatters.Xml;
using Microsoft.AspNetCore.Mvc.Testing;
Expand Down Expand Up @@ -222,20 +223,18 @@ public async Task ProblemDetails_IsSerialized()
// Arrange
using (new ActivityReplacer())
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You could get rid of this type

{
var expected = "<problem xmlns=\"urn:ietf:rfc:7807\">" +
"<status>404</status>" +
"<title>Not Found</title>" +
"<type>https://tools.ietf.org/html/rfc7231#section-6.5.4</type>" +
$"<traceId>{Activity.Current.Id}</traceId>" +
"</problem>";

// Act
var response = await Client.GetAsync("/api/XmlDataContractApi/ActionReturningClientErrorStatusCodeResult");

// Assert
await response.AssertStatusCodeAsync(HttpStatusCode.NotFound);
var content = await response.Content.ReadAsStringAsync();
XmlAssert.Equal(expected, content);
var root = XDocument.Parse(content).Root;
Assert.Equal("404", root.Element(root.Name.Namespace.GetName("status"))?.Value);
Assert.Equal("Not Found", root.Element(root.Name.Namespace.GetName("title"))?.Value);
Assert.Equal("https://tools.ietf.org/html/rfc7231#section-6.5.4", root.Element(root.Name.Namespace.GetName("type"))?.Value);
// Activity is not null
Assert.NotNull(root.Element(root.Name.Namespace.GetName("traceId"))?.Value);
}
}

Expand Down Expand Up @@ -266,22 +265,21 @@ public async Task ValidationProblemDetails_IsSerialized()
// Arrange
using (new ActivityReplacer())
{
var expected = "<problem xmlns=\"urn:ietf:rfc:7807\">" +
"<status>400</status>" +
"<title>One or more validation errors occurred.</title>" +
$"<traceId>{Activity.Current.Id}</traceId>" +
"<MVC-Errors>" +
"<State>The State field is required.</State>" +
"</MVC-Errors>" +
"</problem>";

// Act
var response = await Client.GetAsync("/api/XmlDataContractApi/ActionReturningValidationProblem");

// Assert
await response.AssertStatusCodeAsync(HttpStatusCode.BadRequest);
var content = await response.Content.ReadAsStringAsync();
XmlAssert.Equal(expected, content);
var root = XDocument.Parse(content).Root;

Assert.Equal("400", root.Element(root.Name.Namespace.GetName("status"))?.Value);
Assert.Equal("One or more validation errors occurred.", root.Element(root.Name.Namespace.GetName("title"))?.Value);
var mvcErrors = root.Element(root.Name.Namespace.GetName("MVC-Errors"));
Assert.NotNull(mvcErrors);
Assert.Equal("The State field is required.", mvcErrors.Element(root.Name.Namespace.GetName("State"))?.Value);
// Activity is not null
Assert.NotNull(root.Element(root.Name.Namespace.GetName("traceId"))?.Value);
}
}

Expand Down
Loading