Baggage and Tags for activity tracking options (#46571) (#48722)
authorMarc Sallin <msallin@users.noreply.github.com>
Fri, 12 Mar 2021 17:36:53 +0000 (18:36 +0100)
committerGitHub <noreply@github.com>
Fri, 12 Mar 2021 17:36:53 +0000 (09:36 -0800)
Co-authored-by: Sallin Marc, I212 <marc.sallin@post.ch>
src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs
src/libraries/Microsoft.Extensions.Logging/ref/Microsoft.Extensions.Logging.cs
src/libraries/Microsoft.Extensions.Logging/src/ActivityTrackingOptions.cs
src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs
src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs
src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs
src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/Activity.cs

index 793294c..0f36386 100644 (file)
@@ -109,11 +109,11 @@ namespace Microsoft.Extensions.Logging.Console
                 writer.WriteStartArray("Scopes");
                 scopeProvider.ForEachScope((scope, state) =>
                 {
-                    if (scope is IEnumerable<KeyValuePair<string, object>> scopes)
+                    if (scope is IEnumerable<KeyValuePair<string, object>> scopeItems)
                     {
                         state.WriteStartObject();
                         state.WriteString("Message", scope.ToString());
-                        foreach (KeyValuePair<string, object> item in scopes)
+                        foreach (KeyValuePair<string, object> item in scopeItems)
                         {
                             WriteItem(state, item);
                         }
index fafdc53..bb2d201 100644 (file)
@@ -23,6 +23,8 @@ namespace Microsoft.Extensions.Logging
         ParentId = 4,
         TraceState = 8,
         TraceFlags = 16,
+        Tags = 32,
+        Baggage = 64
     }
     public static partial class FilterLoggingBuilderExtensions
     {
index 044bf86..062c022 100644 (file)
@@ -16,28 +16,38 @@ namespace Microsoft.Extensions.Logging
         None        = 0x0000,
 
         /// <summary>
-        /// Span Id wil be included in the logging.
+        /// Span Id will be included in the logging.
         /// </summary>
         SpanId      = 0x0001,
 
         /// <summary>
-        /// Trace Id wil be included in the logging.
+        /// Trace Id will be included in the logging.
         /// </summary>
         TraceId     = 0x0002,
 
         /// <summary>
-        /// Parent Id wil be included in the logging.
+        /// Parent Id will be included in the logging.
         /// </summary>
         ParentId    = 0x0004,
 
         /// <summary>
-        /// Trace State wil be included in the logging.
+        /// Trace State will be included in the logging.
         /// </summary>
         TraceState  = 0x0008,
 
         /// <summary>
-        /// Trace flags wil be included in the logging.
+        /// Trace flags will be included in the logging.
         /// </summary>
-        TraceFlags  = 0x0010
+        TraceFlags  = 0x0010,
+
+        /// <summary>
+        /// Tags will be included in the logging.
+        /// </summary>
+        Tags        = 0x0020,
+
+        /// <summary>
+        /// Items of baggage will be included in the logging.
+        /// </summary>
+        Baggage     = 0x0040
     }
 }
index 2961d33..c25b12a 100644 (file)
@@ -66,7 +66,9 @@ namespace Microsoft.Extensions.Logging
             _factoryOptions = options == null || options.Value == null ? new LoggerFactoryOptions() : options.Value;
 
             const ActivityTrackingOptions ActivityTrackingOptionsMask = ~(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceId | ActivityTrackingOptions.ParentId |
-                                                                          ActivityTrackingOptions.TraceFlags | ActivityTrackingOptions.TraceState);
+                                                                          ActivityTrackingOptions.TraceFlags | ActivityTrackingOptions.TraceState | ActivityTrackingOptions.Tags
+                                                                          | ActivityTrackingOptions.Baggage);
+
 
             if ((_factoryOptions.ActivityTrackingOptions & ActivityTrackingOptionsMask) != 0)
             {
index 6a55ff2..962f807 100644 (file)
@@ -3,7 +3,6 @@
 
 using System;
 using System.Text;
-using System.Globalization;
 using System.Threading;
 using System.Collections;
 using System.Diagnostics;
@@ -48,12 +47,47 @@ namespace Microsoft.Extensions.Logging
                     }
 
                     callback(activityLogScope, state);
+
+                    // Tags and baggage are opt-in and thus we assume that most of the time it will not be used.
+                    if ((_activityTrackingOption & ActivityTrackingOptions.Tags) != 0
+                        && activity.TagObjects.GetEnumerator().MoveNext())
+                    {
+                        // As TagObjects is a IEnumerable<KeyValuePair<string, object?>> this can be used directly as a scope.
+                        // We do this to safe the allocation of a wrapper object.
+                         callback(activity.TagObjects, state);
+                    }
+
+                    if ((_activityTrackingOption & ActivityTrackingOptions.Baggage) != 0)
+                    {
+                        // Only access activity.Baggage as every call leads to an allocation
+                        IEnumerable<KeyValuePair<string, string?>> baggage = activity.Baggage;
+                        if (baggage.GetEnumerator().MoveNext())
+                        {
+                            // For the baggage a wrapper object is necessary because we need to be able to overwrite ToString().
+                            // In contrast to the TagsObject, Baggage doesn't have one underlining type where we can do this overwrite.
+                            ActivityBaggageLogScopeWrapper scope = GetOrCreateActivityBaggageLogScopeWrapper(activity, baggage);
+                            callback(scope, state);
+                        }
+                    }
                 }
             }
 
             Report(_currentScope.Value);
         }
 
+        private static ActivityBaggageLogScopeWrapper GetOrCreateActivityBaggageLogScopeWrapper(Activity activity, IEnumerable<KeyValuePair<string, string?>> items)
+        {
+            const string additionalItemsBaggagePropertyKey = "__ActivityBaggageItemsLogScope__";
+            var activityBaggageLogScopeWrapper = activity.GetCustomProperty(additionalItemsBaggagePropertyKey) as ActivityBaggageLogScopeWrapper;
+            if (activityBaggageLogScopeWrapper == null)
+            {
+                activityBaggageLogScopeWrapper = new ActivityBaggageLogScopeWrapper(items);
+                activity.SetCustomProperty(additionalItemsBaggagePropertyKey, activityBaggageLogScopeWrapper);
+            }
+
+            return activityBaggageLogScopeWrapper;
+        }
+
         public IDisposable Push(object state)
         {
             Scope parent = _currentScope.Value;
@@ -185,7 +219,59 @@ namespace Microsoft.Extensions.Logging
                 return GetEnumerator();
             }
         }
+
+        private class ActivityBaggageLogScopeWrapper : IEnumerable<KeyValuePair<string, string?>>
+        {
+            private readonly IEnumerable<KeyValuePair<string, string?>> _items;
+
+            private StringBuilder? _stringBuilder;
+
+            public ActivityBaggageLogScopeWrapper (IEnumerable<KeyValuePair<string, string?>> items)
+            {
+                _items = items;
+            }
+
+            public IEnumerator<KeyValuePair<string, string?>> GetEnumerator()
+            {
+                return _items.GetEnumerator();
+            }
+
+            IEnumerator IEnumerable.GetEnumerator()
+            {
+                return _items.GetEnumerator();
+            }
+
+            public override string ToString()
+            {
+                lock (this)
+                {
+                    IEnumerator<KeyValuePair<string, string?>> enumerator = _items.GetEnumerator();
+                    if (!enumerator.MoveNext())
+                    {
+                        return string.Empty;
+                    }
+
+                    _stringBuilder ??= new StringBuilder();
+                    _stringBuilder.Append(enumerator.Current.Key);
+                    _stringBuilder.Append(':');
+                    _stringBuilder.Append(enumerator.Current.Value);
+
+                    while (enumerator.MoveNext())
+                    {
+                        _stringBuilder.Append(", ");
+                        _stringBuilder.Append(enumerator.Current.Key);
+                        _stringBuilder.Append(':');
+                        _stringBuilder.Append(enumerator.Current.Value);
+                    }
+
+                    string result = _stringBuilder.ToString();
+                    _stringBuilder.Clear();
+                    return result;
+                }
+            }
+        }
     }
+
     internal static class ActivityExtensions
     {
         public static string GetSpanId(this Activity activity)
index eb0ef28..e31d7e8 100644 (file)
@@ -3,7 +3,6 @@
 
 using System;
 using System.Text;
-using System.Globalization;
 using System.Diagnostics;
 using System.Collections.Generic;
 using Microsoft.Extensions.DependencyInjection;
@@ -82,6 +81,7 @@ namespace Microsoft.Extensions.Logging.Test
             return disposableProvider.Object;
         }
 
+
         [Fact]
         public void Dispose_ThrowException_SwallowsException()
         {
@@ -181,8 +181,10 @@ namespace Microsoft.Extensions.Logging.Test
 
             var logger = loggerFactory.CreateLogger("Logger");
 
-            Activity a = new Activity("ScopeActivity");
-            a.Start();
+            Activity activity = new Activity("ScopeActivity");
+            activity.AddBaggage("baggageTestKey1", "baggageTestValue");
+            activity.AddTag("tagTestKey", "tagTestValue");
+            activity.Start();
             string activity1String = GetActivityLogString(options);
             string activity2String;
 
@@ -199,10 +201,11 @@ namespace Microsoft.Extensions.Logging.Test
                 }
                 b.Stop();
             }
-            a.Stop();
+            activity.Stop();
 
             Assert.Equal(activity1String, loggerProvider.LogText[1]);
             Assert.Equal(activity2String, loggerProvider.LogText[4]);
+            Assert.Equal(7, loggerProvider.LogText.Count); // Ensure that Baggage and Tags aren't added.
         }
 
         [Fact]
@@ -214,6 +217,195 @@ namespace Microsoft.Extensions.Logging.Test
         }
 
         [Fact]
+        public void TestActivityTrackingOptions_ShouldAddBaggageItemsAsNewScope_WhenBaggageOptionIsSet()
+        {
+            var loggerProvider = new ExternalScopeLoggerProvider();
+
+            var loggerFactory = LoggerFactory.Create(builder =>
+            {
+                builder
+                    .Configure(o => o.ActivityTrackingOptions = ActivityTrackingOptions.Baggage)
+                    .AddProvider(loggerProvider);
+            });
+
+            var logger = loggerFactory.CreateLogger("Logger");
+
+            Activity activity = new Activity("ScopeActivity");
+            activity.AddBaggage("testKey1", null);
+            activity.AddBaggage("testKey2", string.Empty);
+            activity.AddBaggage("testKey3", "testValue");
+            activity.Start();
+
+            logger.LogInformation("Message1");
+
+            activity.Stop();
+
+            foreach (string s in loggerProvider.LogText)
+            {
+                System.Console.WriteLine(s);
+            }
+
+            Assert.Equal("Message1", loggerProvider.LogText[0]);
+            Assert.Equal("testKey3:testValue, testKey2:, testKey1:", loggerProvider.LogText[2]);
+        }
+
+        [Fact]
+        public void TestActivityTrackingOptions_ShouldAddTagsAsNewScope_WhenTagsOptionIsSet()
+        {
+            var loggerProvider = new ExternalScopeLoggerProvider();
+
+            var loggerFactory = LoggerFactory.Create(builder =>
+            {
+                builder
+                    .Configure(o => o.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.Tags)
+                    .AddProvider(loggerProvider);
+            });
+
+            var logger = loggerFactory.CreateLogger("Logger");
+
+            Activity activity = new Activity("ScopeActivity");
+            activity.AddTag("testKey1", null);
+            activity.AddTag("testKey2", string.Empty);
+            activity.AddTag("testKey3", "testValue");
+            activity.AddTag("testKey4", new Dummy());
+            activity.Start();
+
+            logger.LogInformation("Message1");
+
+            activity.Stop();
+
+            Assert.Equal("Message1", loggerProvider.LogText[0]);
+            Assert.Equal("testKey1:, testKey2:, testKey3:testValue, testKey4:DummyToString", loggerProvider.LogText[2]);
+        }
+
+        [Fact]
+        public void TestActivityTrackingOptions_ShouldAddTagsAndBaggageAsOneScopeAndTraceIdAsOtherScope_WhenTagsBaggageAndTraceIdOptionAreSet()
+        {
+            var loggerProvider = new ExternalScopeLoggerProvider();
+
+            var loggerFactory = LoggerFactory.Create(builder =>
+            {
+                builder
+                    .Configure(o => o.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.Baggage | ActivityTrackingOptions.Tags)
+                    .AddProvider(loggerProvider);
+            });
+
+            var logger = loggerFactory.CreateLogger("Logger");
+
+            Activity activity = new Activity("ScopeActivity");
+            activity.AddTag("testTagKey1", "testTagValue");
+            activity.AddBaggage("testBaggageKey1", "testBaggageValue");
+            activity.Start();
+            logger.LogInformation("Message1");
+            string traceIdActivityLogString = GetActivityLogString(ActivityTrackingOptions.TraceId);
+            activity.Stop();
+
+            Assert.Equal("Message1", loggerProvider.LogText[0]);
+            Assert.Equal(traceIdActivityLogString, loggerProvider.LogText[1]);
+            Assert.Equal("testTagKey1:testTagValue", loggerProvider.LogText[2]);
+            Assert.Equal("testBaggageKey1:testBaggageValue", loggerProvider.LogText[3]);
+        }
+
+        [Fact]
+        public void TestActivityTrackingOptions_ShouldAddNewTagAndBaggageItemsAtRuntime_WhenTagsAndBaggageOptionAreSetAndWithNestedScopes()
+        {
+            var loggerProvider = new ExternalScopeLoggerProvider();
+
+            var loggerFactory = LoggerFactory.Create(builder =>
+            {
+                builder
+                    .Configure(o => o.ActivityTrackingOptions = ActivityTrackingOptions.Baggage | ActivityTrackingOptions.Tags)
+                    .AddProvider(loggerProvider);
+            });
+
+            var logger = loggerFactory.CreateLogger("Logger");
+
+            Activity activity = new Activity("ScopeActivity");
+            activity.Start();
+
+            // Add baggage and tag items before the first log entry.
+            activity.AddTag("MyTagKey1", "1");
+            activity.AddBaggage("MyBaggageKey1", "1");
+
+            // Log a message, this should create any cached objects.
+            logger.LogInformation("Message1");
+
+            // Start the first scope, add some more items and log.
+            using (logger.BeginScope("Scope1"))
+            {
+                activity.AddTag("MyTagKey2", "2");
+                activity.AddBaggage("MyBaggageKey2", "2");
+                logger.LogInformation("Message2");
+
+                // Add two additional scopes and also replace some tag and baggage items.
+                using (logger.BeginScope("Scope2"))
+                {
+                    activity.AddTag("MyTagKey3", "3");
+                    activity.AddBaggage("MyBaggageKey3", "3");
+
+                    using (logger.BeginScope("Scope3"))
+                    {
+                        activity.SetTag("MyTagKey3", "4");
+                        activity.SetBaggage("MyBaggageKey3", "4");
+                        logger.LogInformation("Message3");
+                    }
+                }
+
+                // Along with this message we expect all baggage and tags items
+                // as well as the Scope1 but not the Scope2 and Scope3.
+                logger.LogInformation("Message4");
+
+                activity.Stop();
+            }
+
+            Assert.Equal("Message1", loggerProvider.LogText[0]);
+            Assert.Equal("MyTagKey1:1", loggerProvider.LogText[2]);
+            Assert.Equal("MyBaggageKey1:1", loggerProvider.LogText[3]);
+
+            Assert.Equal("Message2", loggerProvider.LogText[4]);
+            Assert.Equal("MyTagKey1:1, MyTagKey2:2", loggerProvider.LogText[6]);
+            Assert.Equal("MyBaggageKey2:2, MyBaggageKey1:1", loggerProvider.LogText[7]);
+            Assert.Equal("Scope1", loggerProvider.LogText[8]);
+
+            Assert.Equal("Message3", loggerProvider.LogText[9]);
+            Assert.Equal("MyTagKey1:1, MyTagKey2:2, MyTagKey3:4", loggerProvider.LogText[11]);
+            Assert.Equal("MyBaggageKey3:4, MyBaggageKey2:2, MyBaggageKey1:1", loggerProvider.LogText[12]);
+            Assert.Equal("Scope1", loggerProvider.LogText[13]);
+            Assert.Equal("Scope2", loggerProvider.LogText[14]);
+            Assert.Equal("Scope3", loggerProvider.LogText[15]);
+
+            Assert.Equal("Message4", loggerProvider.LogText[16]);
+            Assert.Equal("MyTagKey1:1, MyTagKey2:2, MyTagKey3:4", loggerProvider.LogText[18]);
+            Assert.Equal("MyBaggageKey3:4, MyBaggageKey2:2, MyBaggageKey1:1", loggerProvider.LogText[19]);
+            Assert.Equal("Scope1", loggerProvider.LogText[20]);
+        }
+
+        [Fact]
+        public void TestActivityTrackingOptions_ShouldNotAddAdditionalScope_WhenTagsBaggageOptionAreSetButTagsAndBaggageAreEmpty()
+        {
+            var loggerProvider = new ExternalScopeLoggerProvider();
+
+            var loggerFactory = LoggerFactory.Create(builder =>
+            {
+                builder
+                    .Configure(o => o.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.Baggage | ActivityTrackingOptions.Tags)
+                    .AddProvider(loggerProvider);
+            });
+
+            var logger = loggerFactory.CreateLogger("Logger");
+
+            Activity activity = new Activity("ScopeActivity");
+            activity.Start();
+            logger.LogInformation("Message1");
+            string traceIdActivityLogString = GetActivityLogString(ActivityTrackingOptions.TraceId);
+            activity.Stop();
+
+            Assert.Equal("Message1", loggerProvider.LogText[0]);
+            Assert.Equal(traceIdActivityLogString, loggerProvider.LogText[1]);
+            Assert.Equal(2, loggerProvider.LogText.Count); // Ensure that the additional scopes for tags and baggage aren't added.
+        }
+
+        [Fact]
         public void CallsSetScopeProvider_OnSupportedProviders()
         {
             var loggerProvider = new ExternalScopeLoggerProvider();
@@ -367,6 +559,10 @@ namespace Microsoft.Extensions.Logging.Test
             public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
             {
                 LogText.Add(formatter(state, exception));
+
+                // Notice that other ILoggers maybe not call "ToString()" on the scope but enumerate it and this isn't covered by this implementation.
+                // E.g. the SimpleConsoleFormatter calls "ToString()" like it's done here but the "JsonConsoleFormatter" enumerates a scope
+                // if the Scope is of type IEnumerable<KeyValuePair<string, object>>.
                 ScopeProvider.ForEachScope((scope, builder) => builder.Add(scope.ToString()), LogText);
             }
 
@@ -381,6 +577,14 @@ namespace Microsoft.Extensions.Logging.Test
                 return null;
             }
         }
+
+        private class Dummy
+        {
+            public override string ToString()
+            {
+                return "DummyToString";
+            }
+        }
     }
 
     internal static class ActivityExtensions
index b93a715..d000b72 100644 (file)
@@ -1466,6 +1466,8 @@ namespace System.Diagnostics
             private LinkedListNode<KeyValuePair<string, object?>>? _first;
             private LinkedListNode<KeyValuePair<string, object?>>? _last;
 
+            private StringBuilder? _stringBuilder;
+
             public TagsLinkedList(KeyValuePair<string, object?> firstValue, bool set = false) => _last = _first = ((set && firstValue.Value == null) ? null : new LinkedListNode<KeyValuePair<string, object?>>(firstValue));
 
             public TagsLinkedList(IEnumerator<KeyValuePair<string, object?>> e)
@@ -1627,6 +1629,37 @@ namespace System.Diagnostics
                     current = current.Next;
                 };
             }
+
+            public override string ToString()
+            {
+                lock (this)
+                {
+                    if (_first == null)
+                    {
+                        return string.Empty;
+                    }
+
+                    _stringBuilder ??= new StringBuilder();
+                    _stringBuilder.Append(_first.Value.Key);
+                    _stringBuilder.Append(':');
+                    _stringBuilder.Append(_first.Value.Value);
+
+                    LinkedListNode<KeyValuePair<string, object?>>? current = _first.Next;
+                    while (current != null)
+                    {
+                        _stringBuilder.Append(", ");
+                        _stringBuilder.Append(current.Value.Key);
+                        _stringBuilder.Append(':');
+                        _stringBuilder.Append(current.Value.Value);
+
+                        current = current.Next;
+                    }
+
+                    string result = _stringBuilder.ToString();
+                    _stringBuilder.Clear();
+                    return result;
+                }
+            }
         }
 
         // Note: Some consumers use this Enumerator dynamically to avoid allocations.