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