From e27554390bdbebd3020f8a0fa7d5082c418862f4 Mon Sep 17 00:00:00 2001 From: Marc Sallin Date: Sat, 6 Mar 2021 15:58:49 +0100 Subject: [PATCH 1/3] Rename misleading local variable name --- .../src/JsonConsoleFormatter.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs b/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs index 793294ce2a1870..0f363860cc9a78 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs @@ -109,11 +109,11 @@ private void WriteScopeInformation(Utf8JsonWriter writer, IExternalScopeProvider writer.WriteStartArray("Scopes"); scopeProvider.ForEachScope((scope, state) => { - if (scope is IEnumerable> scopes) + if (scope is IEnumerable> scopeItems) { state.WriteStartObject(); state.WriteString("Message", scope.ToString()); - foreach (KeyValuePair item in scopes) + foreach (KeyValuePair item in scopeItems) { WriteItem(state, item); } From bee1e0b9efa20e16c90fb0314e730fd349d2e44d Mon Sep 17 00:00:00 2001 From: "Sallin Marc, I212" Date: Tue, 23 Feb 2021 20:18:10 +0100 Subject: [PATCH 2/3] Add tags and baggage options to ActivityTrackingOptions (#46571) --- .../ref/Microsoft.Extensions.Logging.cs | 2 ++ .../src/ActivityTrackingOptions.cs | 22 ++++++++++++++----- 2 files changed, 18 insertions(+), 6 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Logging/ref/Microsoft.Extensions.Logging.cs b/src/libraries/Microsoft.Extensions.Logging/ref/Microsoft.Extensions.Logging.cs index fafdc5319da6b6..bb2d201cca3207 100644 --- a/src/libraries/Microsoft.Extensions.Logging/ref/Microsoft.Extensions.Logging.cs +++ b/src/libraries/Microsoft.Extensions.Logging/ref/Microsoft.Extensions.Logging.cs @@ -23,6 +23,8 @@ public enum ActivityTrackingOptions ParentId = 4, TraceState = 8, TraceFlags = 16, + Tags = 32, + Baggage = 64 } public static partial class FilterLoggingBuilderExtensions { diff --git a/src/libraries/Microsoft.Extensions.Logging/src/ActivityTrackingOptions.cs b/src/libraries/Microsoft.Extensions.Logging/src/ActivityTrackingOptions.cs index 044bf8664d18f0..062c022dbc01ad 100644 --- a/src/libraries/Microsoft.Extensions.Logging/src/ActivityTrackingOptions.cs +++ b/src/libraries/Microsoft.Extensions.Logging/src/ActivityTrackingOptions.cs @@ -16,28 +16,38 @@ public enum ActivityTrackingOptions None = 0x0000, /// - /// Span Id wil be included in the logging. + /// Span Id will be included in the logging. /// SpanId = 0x0001, /// - /// Trace Id wil be included in the logging. + /// Trace Id will be included in the logging. /// TraceId = 0x0002, /// - /// Parent Id wil be included in the logging. + /// Parent Id will be included in the logging. /// ParentId = 0x0004, /// - /// Trace State wil be included in the logging. + /// Trace State will be included in the logging. /// TraceState = 0x0008, /// - /// Trace flags wil be included in the logging. + /// Trace flags will be included in the logging. /// - TraceFlags = 0x0010 + TraceFlags = 0x0010, + + /// + /// Tags will be included in the logging. + /// + Tags = 0x0020, + + /// + /// Items of baggage will be included in the logging. + /// + Baggage = 0x0040 } } From 7e64b803662be30aa89dad717ec622380b02057e Mon Sep 17 00:00:00 2001 From: Marc Sallin Date: Wed, 24 Feb 2021 22:17:57 +0100 Subject: [PATCH 3/3] Add tags and baggage as log scope (#46571) --- .../src/LoggerFactory.cs | 4 +- .../src/LoggerFactoryScopeProvider.cs | 88 +++++++- .../tests/Common/LoggerFactoryTest.cs | 212 +++++++++++++++++- .../src/System/Diagnostics/Activity.cs | 33 +++ 4 files changed, 331 insertions(+), 6 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs index 2961d333b40c14..c25b12a0ce1a33 100644 --- a/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs +++ b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs @@ -66,7 +66,9 @@ public LoggerFactory(IEnumerable providers, IOptionsMonitor> 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> 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> 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 @@ IEnumerator IEnumerable.GetEnumerator() return GetEnumerator(); } } + + private class ActivityBaggageLogScopeWrapper : IEnumerable> + { + private readonly IEnumerable> _items; + + private StringBuilder? _stringBuilder; + + public ActivityBaggageLogScopeWrapper (IEnumerable> items) + { + _items = items; + } + + public IEnumerator> GetEnumerator() + { + return _items.GetEnumerator(); + } + + IEnumerator IEnumerable.GetEnumerator() + { + return _items.GetEnumerator(); + } + + public override string ToString() + { + lock (this) + { + IEnumerator> 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) diff --git a/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs b/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs index eb0ef289f10578..e31d7e8c26c135 100644 --- a/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs +++ b/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs @@ -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 @@ private static ILoggerProvider CreateProvider() return disposableProvider.Object; } + [Fact] public void Dispose_ThrowException_SwallowsException() { @@ -181,8 +181,10 @@ public void TestActivityIds(ActivityTrackingOptions options) 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 @@ public void TestActivityIds(ActivityTrackingOptions options) } 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] @@ -213,6 +216,195 @@ public void TestInvalidActivityTrackingOptions() ); } + [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() { @@ -367,6 +559,10 @@ public ILogger CreateLogger(string categoryName) public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func 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>. ScopeProvider.ForEachScope((scope, builder) => builder.Add(scope.ToString()), LogText); } @@ -381,6 +577,14 @@ public IDisposable BeginScope(TState state) return null; } } + + private class Dummy + { + public override string ToString() + { + return "DummyToString"; + } + } } internal static class ActivityExtensions diff --git a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/Activity.cs b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/Activity.cs index ee225a14ae9b6a..2411f2e19ca39f 100644 --- a/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/Activity.cs +++ b/src/libraries/System.Diagnostics.DiagnosticSource/src/System/Diagnostics/Activity.cs @@ -1458,6 +1458,8 @@ private class TagsLinkedList : IEnumerable> private LinkedListNode>? _first; private LinkedListNode>? _last; + private StringBuilder? _stringBuilder; + public TagsLinkedList(KeyValuePair firstValue, bool set = false) => _last = _first = ((set && firstValue.Value == null) ? null : new LinkedListNode>(firstValue)); public TagsLinkedList(IEnumerator> e) @@ -1619,6 +1621,37 @@ public void Set(KeyValuePair value) 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>? 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.