Add activity Ids and Context to all logs

[tarekgh]

This issue tracking the work as the part of the issue #31372

Rationale and Use Cases

Currently, there is no automatic way to log the tracing context info with the logging scopes. Tracing context info is the trace Id, Span Id, Parent Id, Trace State, and Trace flags which included inside the Activity object stored in the current execution context. This issue is to support adding the tracing context info with the logging scopes.

Adding Tracing context info to the logging scope will require some memory allocations and also will increase the produced text inside the logs, we are going to provide an opt-in option to enable the new behavior. Although the whole feature is about internal implementation details, we still need to expose some API for the opt-in option. All Proposed APIs here are only to provide the opt-in option for enabling the trace context info in logging and choose which parts of the trace context should be included.

Here is a code sample showing how to opt-in to include the trace context info in the logs.

var loggerFactory = LoggerFactory.Create(builder =>
{
    // Enable logging trace context info in the logging scopes.
    builder.Configure(factoryOptions => factoryOptions.ActivityTrackingOptions = ActivityTrackingOptions.Default);
});

When enable trace context info logging, will get in the logging results like the following:

info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]
      => SpanId:|30de9810-4985f5593b3c7f14.1., TraceId:30de9810-4985f5593b3c7f14, ParentId:|30de9810-4985f5593b3c7f14. => { Scope1 = 1 } => { Scope2 = 2 }

Proposed API

• ActiviyTrackingOptions is a flags enum has the values of which parts of the trace context can be included in the logs.
• LoggerFactoryOptions is the new options type for the logger factory. Although it contains the only property ActivityTrackingOptions used to enable the trace context logging, this type can be extended in the future to include more options as needed.

namespace Microsoft.Extensions.Logging
{
    [Flags]
    public enum ActivityTrackingOptions
    {
        None        = 0x0000,
        SpanId      = 0x0001,
        TraceId     = 0x0002,
        ParentId    = 0x0004,
        Default     = SpanId | TraceId | ParentId,
        TraceState  = 0x0008,
        TraceFlags  = 0x0010
    }

    public class LoggerFactoryOptions
    {
        public LoggerFactoryOptions() { }
        public ActivityTrackingOptions ActivityTrackingOptions  { get {throw null; } set { throw null; } }
    }
}

• Adding more constructors to the existing LoggerFactory class. This addition mainly to have the Dependency Injection (DI) work nicely with the introduced LoggerFactoryOptions.

namespace Microsoft.Extensions.Logging
{
    // LoggerFactory is existing type
    public partial class LoggerFactory : ILoggerFactory, System.IDisposable
    {
        public LoggerFactory(IOptions<LoggerFactoryOptions> options) { }
        public LoggerFactory(IEnumerable<ILoggerProvider> providers, IOptions<LoggerFactoryOptions> options) { }
        public LoggerFactory(IEnumerable<ILoggerProvider> providers, LoggerFilterOptions filterOptions, IOptions<LoggerFactoryOptions> options) { }
        public LoggerFactory(IEnumerable<ILoggerProvider> providers, IOptionsMonitor<LoggerFilterOptions> filterOption, IOptions<LoggerFactoryOptions> options) { }
     }
}

• Adding the extension method Configure to the logger builder

namespace Microsoft.Extensions.Logging
{
    // LoggingBuilderExtensions is existing type
    public static partial class LoggingBuilderExtensions
    {
        public static ILoggingBuilder Configure(this ILoggingBuilder builder, Action<LoggerFactoryOptions> action) {...}
    }
}

[tarekgh]

@davidfowl could you please make this issue as needed and assign it to yourself?

[benaadams]

https://github.com/dotnet/corefx/issues/42305

[benaadams]

Concerned by "all logs"; more specifically I have high-throughput applications where I do not want the allocation of a requestId or Activity per request (and others where its useful)

[davidfowl]

@benaadams This won't introduce any new allocations. We'll likely also do something like what's in this PR dotnet/extensions#2434 (so you can avoid more allocations).

[Scooletz]

@davidfowl I took a look at the PR you mentioned. One thing is not clear to me. Does this mean that for a logger to support activity ids/context, a logger provider will need to implement ISupportExternalScope and support the external scope? Or will it be either the external scope or a call to ILogger.Scope with the mentioned values?

[davidfowl]

dotnet/aspnetcore#11211 - This was the original PR to put the activity information into the logging scope.

The plan now is to do it in the logger implicitly so that the current Activity is part of the scope by default.

using System;
using System.Diagnostics;
using Microsoft.Extensions.Logging;

namespace ConsoleApp2
{
    class Program
    {
        static void Main(string[] args)
        {
            using var loggerFactory = LoggerFactory.Create(builder =>
            {
                builder.AddConsole(o =>
                {
                    // Print out scope information to the console
                    o.IncludeScopes = true;
                });
            });

            var logger = loggerFactory.CreateLogger<Program>();

            // Logging using a manual scope
            using (logger.BeginScope(new { A = 1 }))
            {
                logger.LogInformation("This is a test");
            }

            // Today logging with an activity doesn't automatically add it to the scope, this is the change
            // we want to make work with this change. It should be opt-out in the logger factory.
            var activity1 = new Activity("MyActivity");
            activity1.Start();
            logger.LogInformation("This is another test");
            activity1.Stop();


            // Manually adding the activity information to the logging scope. This is what customers have to do today.
            var activity2 = new Activity("MyActivity2");
            activity2.Start();
            using (logger.BeginScope(new { activity2.TraceId, ParentId = activity2.ParentSpanId, activity2.SpanId }))
            {
                logger.LogInformation("This is another test");
            }
            activity2.Stop();

        }
    }
}

As for implementations I can think of a few techniques:

1. We could return an implicit scope entry from the default IExternalScope provider implementation, here

   runtime/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerExternalScopeProvider.cs

   Line 24 in d9b1a28

   public void ForEachScope<TState>(Action<object, TState> callback, TState state)

   . ILoggers can use this to manage their scopes and the factory manages the use of async local to push and pop scopes. ForEach is an efficient way for loggers to get access to the scope information e.g.

   runtime/src/libraries/Microsoft.Extensions.Logging.EventLog/src/EventLogLogger.cs

   Line 96 in e3ffd34

   _externalScopeProvider?.ForEachScope((scope, sb) =>

2. The other way would be to update all of the logger provider implementations to directly access the activity and log add it to the scope.

We need a way to turn this behavior off as well. Likely an option on the provider or factory depending on where we put this behavior.

For 1. I'd imagine the code would look like this:

public void ForEachScope<TState>(Action<object, TState> callback, TState state)
{
    void Report(Scope current)
    {
        if (current == null)
        {
            return;
        }
        Report(current.Parent);
        callback(current.State, state);
    }
    if (Activity.Current != null)
    {
        // Unfortunate allocation, can potentially be cached on the activity itself...
        callback(new ActivityLogScope(Activity.Current), state);
    }
    Report(_currentScope.Value);
}

ActivityLogScope

private class ActivityLogScope : IReadOnlyList<KeyValuePair<string, object>>
{
    private readonly Activity _activity;

    private string _cachedToString;

    public int Count
    {
        get
        {
            return 3;
        }
    }

    public KeyValuePair<string, object> this[int index]
    {
        get
        {
            if (index == 0)
            {
                return new KeyValuePair<string, object>("SpanId", _activity.GetSpanId());
            }
            else if (index == 1)
            {
                return new KeyValuePair<string, object>("TraceId", _activity.GetTraceId());
            }
            else if (index == 2)
            {
                return new KeyValuePair<string, object>("ParentId", _activity.GetParentId());
            }

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

    public ActivityLogScope(Activity activity)
    {
        _activity = activity;
    }

    public override string ToString()
    {
        if (_cachedToString == null)
        {
            _cachedToString = string.Format(
                CultureInfo.InvariantCulture,
                "SpanId:{0}, TraceId:{1}, ParentId:{2}",
                _activity.GetSpanId(),
                _activity.GetTraceId(),
                _activity.GetParentId());
        }

        return _cachedToString;
    }

    public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
    {
        for (int i = 0; i < Count; ++i)
        {
            yield return this[i];
        }
    }

    IEnumerator IEnumerable.GetEnumerator()
    {
        return GetEnumerator();
    }
}

ActivityExtensions.cs

[davidfowl]

cc @pakrym

[tarekgh]

@davidfowl thanks for the write-up.

• It looks the first proposed solution is more reasonable to go with as we don't have to touch all logger providers and also if we introduced more providers in the future that solution will work seamlessly I guess.
• For the opt-out mechanism, if we go with the first solution, I assume we'll need to have some property on LoggerExternalScopeProvider something like:

public bool EnableActivityLogging { get; set; } = true;

of course, we can discuss the property name more.

• Regarding the ActivityLogScope caching comment, do you think if use the new Activity API Set/GetCustomProperty to cache it would help? or this can cause any perf issue (to retrieve the value from Activity dictionary)? or we may run into a scenario in which new updated logging extensions library will be used with the old version of Activity's library (System.Diagnostics.DiagnosticSource) which doesn't have the new API?
• Do we have to care about the scenario if someone uses the non-default scope provider (LoggerExternalScopeProvider)?
• I assume we need to retrieve the trace id, span id and parent id the same way as done in https://github.com/dotnet/aspnetcore/pull/11211/files which is considering the Activity.IdFormat. right?

[tarekgh]

One more idea we can use to reduce the allocation of the ActivityLogScope object is to use a thread-local object in which we can update the activity object in that instance before passing it to the callback. @davidfowl what you think about this idea?

[davidfowl]

@tarekgh not a thread local but an another async local. @pakrym's idea was that we could stash an async local that stores both the activity and this activity scope, and only allocate if it changed a new activity scope if it changes.

[tarekgh]

I am not sure having another Asynclocal would be better. if this is the case, we can stick the object to the Activity through SetCustomProperty as I suggested earlier. Activity Current is already stored in async local anyway. Also, we'll allocate it only when it is requested.

I proposed thread-local which means we'll allocate max one object per thread and only when it is needed. I believe this would be much cheaper. My thinking is according to comparing the number of Activities to number of threads used in our logging scenarios.

[pakrym]

We already have an async local in the scope provider that we use for scopes, we can store a second value in it.

[tarekgh]

Oh, I didn't know that :-) thanks for pointing out at that.

[reyang]

The proposal looks quite good to me.

Some minor questions/comments:

• Do we need ParentId? Is this for compatibility or interop with non-W3C-TraceContext format?
• We might need TraceState or the TraceFlags. This can be extended as we add more options to LoggerFactoryOptions.
• I wonder if it might be a good idea to use bit flags versus bool. Consider a potential scenario EnableActivityTracking BITWISE OR EnableTraceStateTracking.
• Ideally I would love to have a callback to enrich the log, which will run under the Activity context. This is probably something too big to fit here (.NET 5 time frame) though.

Prior arts in OpenCensus Python logging integration: https://github.com/census-instrumentation/opencensus-python/tree/master/contrib/opencensus-ext-logging#opencensus-logging-integration

[tarekgh]

Do we need ParentId? Is this for compatibility or interop with non-W3C-TraceContext format?

Good question. I included the parent according to aspnet core implementation https://github.com/dotnet/aspnetcore/blob/9d2b9e92c68b61e12f41b33efee57bf561e023c4/src/Hosting/Hosting/src/Internal/ActivityExtensions.cs. @davidfowl may advise if this is needed. This issue will not affect the public API, so we can decide about it without any need to change the proposed APIs.

We might need TraceState or the TraceFlags. This can be extended as we add more options to LoggerFactoryOptions.
I wonder if it might be a good idea to use bit flags versus bool. Consider a potential scenario EnableActivityTracking BITWISE OR EnableTraceStateTracking.

Should we include TraceState or the TraceFlags by default? or you think wouldn't be useful most of the time? I mean do we really need to have separate options to include/exclude these?

Ideally I would love to have a callback to enrich the log, which will run under the Activity context. This is probably something too big to fit here (.NET 5 time frame) though.

This is something we can talk about and plan for it if it is an important scenario we need to support. I love to get more information about that.

[tarekgh]

I think @shirhatti may help too telling about aspnet scenario if need to include ParentId, TraceState or the TraceFlags.

[reyang]

We might need TraceState or the TraceFlags. This can be extended as we add more options to LoggerFactoryOptions.
I wonder if it might be a good idea to use bit flags versus bool. Consider a potential scenario EnableActivityTracking BITWISE OR EnableTraceStateTracking.

Should we include TraceState or the TraceFlags by default? or you think wouldn't be useful most of the time? I mean do we really need to have separate options to include/exclude these?

I don't have an authoritative answer at this moment 😄
Personally I'm guessing TraceFlags would be more useful, and TraceState might just be too much for every single log entry. Just for reference:

• In OpenCensus Python we decided to have TraceFlags but not TraceState for log enrichment (I was main driver/decision maker and basically following my instinct + consideration of sampling decision - log samplers might take advantage of TraceFlags but not TraceState)
• In OpenTelemetry there is an on-going logging SIG discussion, and this seems to be the current direction https://github.com/open-telemetry/oteps/pull/97/files#r419752394.

Ideally I would love to have a callback to enrich the log, which will run under the Activity context. This is probably something too big to fit here (.NET 5 time frame) though.

This is something we can talk about and plan for it if it is an important scenario we need to support. I love to get more information about that.

Sure! Let's focus on the .NET 5 scope here and take this into a separate discussion.

[davidfowl]

Should we include TraceState or the TraceFlags by default? or you think wouldn't be useful most of the time? I mean do we really need to have separate options to include/exclude these?

No we shouldn't. If this becomes a thing we should have a flags enum instead of a bool that describe what pieces of the activity to include. I don't think we should include trace state or flags by default though.

[tarekgh]

Ok, it sounds having flags enum will give us some flexibility. I can try updating the proposal as:

    [Flags]
    public enum ActiviyTrackingOptions
    {
        None        = 0x0000,
        SpanId      = 0x0001,
        TraceId     = 0x0002,
        ParentId    = 0x0004,
        TraceState  = 0x0008,
        TraceFlags  = 0x0010
    }

    public class LoggerFactoryOptions
    {
        public LoggerFactoryOptions() { }
        public ActiviyTrackingOptions ActivityTrackingOptions  { get {throw null; } set { throw null; } }
    }

    public partial class LoggerExternalScopeProvider : IExternalScopeProvider
    {
        public LoggerExternalScopeProvider(ActiviyTrackingOptions activityTrackingOptions) { }
    }

@davidfowl what do you think?
Please note the constructor LoggerExternalScopeProvider is going to take ActiviyTrackingOptions parameter. that means ActiviyTrackingOptions is going to be defined in the Abstraction package and not in the Logging package. Also, do you think this constructor should take LoggerFactoryOptions as a parameter instead? if so, this will mean we'll have to have LoggerFactoryOptions in the Abstraction package and not in the Logging package.

[tarekgh]

Talked offline with @davidfowl and we decided to include the flags enum with adding the Default value (which will be including SpanId, TraceId, and ParentId). Also, we are going to remove the changes in LoggerExternalScopeProvider and we'll use internal implementation instead. I have updated the proposal according that. I'll work modifying my implementation too.

[reyang]

Thanks @davidfowl @tarekgh!

[tarekgh]

thanks @reyang for your valuable feedback.

[terrajobst]

Video

• We should remove ActivityTrackingOptions.Default because we can't change its value ever. Instead, we should just set the value in the LoggerFactoryOptions contructor
• We should make sure that default parameters in constructors are part of the spec that 3rd party DI containers have to support

namespace Microsoft.Extensions.Logging
{
    [Flags]
    public enum ActivityTrackingOptions
    {
        None        = 0x0000,
        SpanId      = 0x0001,
        TraceId     = 0x0002,
        ParentId    = 0x0004,
        TraceState  = 0x0008,
        TraceFlags  = 0x0010
    }
    public class LoggerFactoryOptions
    {
        public LoggerFactoryOptions();
        public ActivityTrackingOptions ActivityTrackingOptions  { get; set; }
    }
    public partial class LoggerFactory
    {
        public LoggerFactory(IEnumerable<ILoggerProvider> providers,
                             IOptionsMonitor<LoggerFilterOptions> filterOption,
                             IOptions<LoggerFactoryOptions> options = null);
    }
    public static partial class LoggingBuilderExtensions
    {
        public static ILoggingBuilder Configure(this ILoggingBuilder builder,
                                                Action<LoggerFactoryOptions> action);
    }
}