From 17cabc13a11ab68443fb5940b9a9c64f27c89960 Mon Sep 17 00:00:00 2001 From: Tarek Mahmoud Sayed Date: Wed, 27 May 2020 13:52:35 -0700 Subject: [PATCH 1/5] Add activity Ids and Context to log scopes --- .../ref/Microsoft.Extensions.Logging.cs | 17 ++ .../src/ActivityTrackingOptions.cs | 44 ++++ .../src/LoggerFactory.cs | 19 +- .../src/LoggerFactoryOptions.cs | 24 ++ .../src/LoggerFactoryScopeProvider.cs | 224 ++++++++++++++++++ .../src/LoggingBuilderExtensions.cs | 13 + .../src/Microsoft.Extensions.Logging.csproj | 4 + .../tests/Common/ConsoleLoggerTest.cs | 115 +++++++++ .../Microsoft.Extensions.Logging.Tests.csproj | 1 + 9 files changed, 458 insertions(+), 3 deletions(-) create mode 100644 src/libraries/Microsoft.Extensions.Logging/src/ActivityTrackingOptions.cs create mode 100644 src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryOptions.cs create mode 100644 src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs 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 a3302a6411a1d..9fd2196591be7 100644 --- a/src/libraries/Microsoft.Extensions.Logging/ref/Microsoft.Extensions.Logging.cs +++ b/src/libraries/Microsoft.Extensions.Logging/ref/Microsoft.Extensions.Logging.cs @@ -40,12 +40,28 @@ public partial interface ILoggingBuilder { Microsoft.Extensions.DependencyInjection.IServiceCollection Services { get; } } + [System.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 {throw null; } set { throw null; } } + } public partial class LoggerFactory : Microsoft.Extensions.Logging.ILoggerFactory, System.IDisposable { public LoggerFactory() { } public LoggerFactory(System.Collections.Generic.IEnumerable providers) { } public LoggerFactory(System.Collections.Generic.IEnumerable providers, Microsoft.Extensions.Logging.LoggerFilterOptions filterOptions) { } public LoggerFactory(System.Collections.Generic.IEnumerable providers, Microsoft.Extensions.Options.IOptionsMonitor filterOption) { } + public LoggerFactory(System.Collections.Generic.IEnumerable providers, Microsoft.Extensions.Options.IOptionsMonitor filterOption, Microsoft.Extensions.Options.IOptions options = null) { } public void AddProvider(Microsoft.Extensions.Logging.ILoggerProvider provider) { } protected virtual bool CheckDisposed() { throw null; } public static Microsoft.Extensions.Logging.ILoggerFactory Create(System.Action configure) { throw null; } @@ -73,6 +89,7 @@ public static partial class LoggingBuilderExtensions public static Microsoft.Extensions.Logging.ILoggingBuilder AddProvider(this Microsoft.Extensions.Logging.ILoggingBuilder builder, Microsoft.Extensions.Logging.ILoggerProvider provider) { throw null; } public static Microsoft.Extensions.Logging.ILoggingBuilder ClearProviders(this Microsoft.Extensions.Logging.ILoggingBuilder builder) { throw null; } public static Microsoft.Extensions.Logging.ILoggingBuilder SetMinimumLevel(this Microsoft.Extensions.Logging.ILoggingBuilder builder, Microsoft.Extensions.Logging.LogLevel level) { throw null; } + public static Microsoft.Extensions.Logging.ILoggingBuilder Configure(this Microsoft.Extensions.Logging.ILoggingBuilder builder, System.Action action) { throw null; } } [System.AttributeUsageAttribute(System.AttributeTargets.Class, AllowMultiple=false, Inherited=false)] public partial class ProviderAliasAttribute : System.Attribute diff --git a/src/libraries/Microsoft.Extensions.Logging/src/ActivityTrackingOptions.cs b/src/libraries/Microsoft.Extensions.Logging/src/ActivityTrackingOptions.cs new file mode 100644 index 0000000000000..a1dce22f01ae9 --- /dev/null +++ b/src/libraries/Microsoft.Extensions.Logging/src/ActivityTrackingOptions.cs @@ -0,0 +1,44 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. +using System; + +namespace Microsoft.Extensions.Logging +{ + /// + /// Flags to indicate which trace context parts should be included with the logging scopes. + /// + [Flags] + public enum ActivityTrackingOptions + { + /// + /// None of the trace context part wil be included in the logging. + /// + None = 0x0000, + + /// + /// Span Id wil be included in the logging. + /// + SpanId = 0x0001, + + /// + /// Trace Id wil be included in the logging. + /// + TraceId = 0x0002, + + /// + /// Parent Id wil be included in the logging. + /// + ParentId = 0x0004, + + /// + /// Trace State wil be included in the logging. + /// + TraceState = 0x0008, + + /// + /// Trace flags wil be included in the logging. + /// + TraceFlags = 0x0010 + } +} \ No newline at end of file diff --git a/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs index 92b2e29e83afc..903a8bf82c5ff 100644 --- a/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs +++ b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs @@ -23,7 +23,8 @@ public class LoggerFactory : ILoggerFactory private volatile bool _disposed; private IDisposable _changeTokenRegistration; private LoggerFilterOptions _filterOptions; - private LoggerExternalScopeProvider _scopeProvider; + private LoggerFactoryScopeProvider _scopeProvider; + private LoggerFactoryOptions _factoryOptions; /// /// Creates a new instance. @@ -54,8 +55,20 @@ public LoggerFactory() : this(Enumerable.Empty()) /// /// The providers to use in producing instances. /// The filter option to use. - public LoggerFactory(IEnumerable providers, IOptionsMonitor filterOption) + public LoggerFactory(IEnumerable providers, IOptionsMonitor filterOption) : this(providers, filterOption, null) { + } + + /// + /// Creates a new instance. + /// + /// The providers to use in producing instances. + /// The filter option to use. + /// The . + public LoggerFactory(IEnumerable providers, IOptionsMonitor filterOption, IOptions options = null) + { + _factoryOptions = options == null || options.Value == null ? new LoggerFactoryOptions() : options.Value; + foreach (var provider in providers) { AddProviderRegistration(provider, dispose: false); @@ -164,7 +177,7 @@ private void AddProviderRegistration(ILoggerProvider provider, bool dispose) { if (_scopeProvider == null) { - _scopeProvider = new LoggerExternalScopeProvider(); + _scopeProvider = new LoggerFactoryScopeProvider(_factoryOptions.ActivityTrackingOptions); } supportsExternalScope.SetScopeProvider(_scopeProvider); diff --git a/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryOptions.cs b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryOptions.cs new file mode 100644 index 0000000000000..0a3c85c797876 --- /dev/null +++ b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryOptions.cs @@ -0,0 +1,24 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Collections.Generic; + +namespace Microsoft.Extensions.Logging +{ + /// + /// The options for a LoggerFactory. + /// + public class LoggerFactoryOptions + { + /// + /// Creates a new instance. + /// + public LoggerFactoryOptions() { } + + /// + /// Gets or sets value to indicate which parts of the tracing context information should be included with the logging scopes. + /// + public ActivityTrackingOptions ActivityTrackingOptions { get; set; } + } +} diff --git a/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs new file mode 100644 index 0000000000000..86fba14b14e74 --- /dev/null +++ b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs @@ -0,0 +1,224 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Text; +using System.Globalization; +using System.Threading; +using System.Collections; +using System.Diagnostics; +using System.Collections.Generic; + +namespace Microsoft.Extensions.Logging +{ + /// + /// Default implementation of + /// + internal class LoggerFactoryScopeProvider : IExternalScopeProvider + { + private readonly AsyncLocal _currentScope = new AsyncLocal(); + private ActivityTrackingOptions _activityTrackingOption; + + public LoggerFactoryScopeProvider(ActivityTrackingOptions activityTrackingOption) => _activityTrackingOption = activityTrackingOption; + + public void ForEachScope(Action callback, TState state) + { + void Report(Scope current) + { + if (current == null) + { + return; + } + Report(current.Parent); + callback(current.State, state); + } + + if (_activityTrackingOption != ActivityTrackingOptions.None) + { + Activity activity = Activity.Current; + if (activity != null) + { + const string propertyKey = "__ActivityLogScope__"; + + ActivityLogScope activityLogScope = activity.GetCustomProperty(propertyKey) as ActivityLogScope; + if (activityLogScope == null) + { + activityLogScope = new ActivityLogScope(activity, _activityTrackingOption); + activity.SetCustomProperty(propertyKey, activityLogScope); + } + + callback(activityLogScope, state); + } + } + + Report(_currentScope.Value); + } + + public IDisposable Push(object state) + { + var parent = _currentScope.Value; + var newScope = new Scope(this, state, parent); + _currentScope.Value = newScope; + + return newScope; + } + + private class Scope : IDisposable + { + private readonly LoggerFactoryScopeProvider _provider; + private bool _isDisposed; + + internal Scope(LoggerFactoryScopeProvider provider, object state, Scope parent) + { + _provider = provider; + State = state; + Parent = parent; + } + + public Scope Parent { get; } + + public object State { get; } + + public override string ToString() + { + return State?.ToString(); + } + + public void Dispose() + { + if (!_isDisposed) + { + _provider._currentScope.Value = Parent; + _isDisposed = true; + } + } + } + + private class ActivityLogScope : IReadOnlyList> + { + private readonly Activity _activity; + private readonly ActivityTrackingOptions _activityTrackingOption; + + private string _cachedToString; + + public int Count + { + get + { + return 3; + } + } + + public KeyValuePair this[int index] + { + get + { + if (index == 0) + { + return new KeyValuePair("SpanId", _activity.GetSpanId()); + } + else if (index == 1) + { + return new KeyValuePair("TraceId", _activity.GetTraceId()); + } + else if (index == 2) + { + return new KeyValuePair("ParentId", _activity.GetParentId()); + } + + throw new ArgumentOutOfRangeException(nameof(index)); + } + } + + public ActivityLogScope(Activity activity, ActivityTrackingOptions activityTrackingOption) + { + Debug.Assert(activityTrackingOption != ActivityTrackingOptions.None); + _activityTrackingOption = activityTrackingOption; + _activity = activity; + } + + public override string ToString() + { + if (_cachedToString == null) + { + StringBuilder sb = new StringBuilder(); + if ((_activityTrackingOption & ActivityTrackingOptions.SpanId) != 0) + { + sb.Append($"SpanId:{_activity.GetSpanId()}"); + } + + if ((_activityTrackingOption & ActivityTrackingOptions.TraceId) != 0) + { + sb.Append(sb.Length > 0 ? $", TraceId:{_activity.GetTraceId()}" : $"TraceId:{_activity.GetTraceId()}"); + } + + if ((_activityTrackingOption & ActivityTrackingOptions.ParentId) != 0) + { + sb.Append(sb.Length > 0 ? $", ParentId:{_activity.GetParentId()}" : $"TraceId:{_activity.GetParentId()}"); + } + + if ((_activityTrackingOption & ActivityTrackingOptions.TraceFlags) != 0) + { + sb.Append(sb.Length > 0 ? $", TraceFlags:{_activity.ActivityTraceFlags}" : $"TraceFlags:{_activity.ActivityTraceFlags}"); + } + + if ((_activityTrackingOption & ActivityTrackingOptions.TraceState) != 0 && _activity.TraceStateString != null) + { + sb.Append(sb.Length > 0 ? $", TraceState:{_activity.TraceStateString}" : $"TraceState:{_activity.TraceStateString}"); + } + + _cachedToString = sb.ToString(); + + } + + return _cachedToString; + } + + public IEnumerator> GetEnumerator() + { + for (int i = 0; i < Count; ++i) + { + yield return this[i]; + } + } + + IEnumerator IEnumerable.GetEnumerator() + { + return GetEnumerator(); + } + } + } + internal static class ActivityExtensions + { + public static string GetSpanId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.Id, + ActivityIdFormat.W3C => activity.SpanId.ToHexString(), + _ => null, + } ?? string.Empty; + } + + public static string GetTraceId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.RootId, + ActivityIdFormat.W3C => activity.TraceId.ToHexString(), + _ => null, + } ?? string.Empty; + } + + public static string GetParentId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.ParentId, + ActivityIdFormat.W3C => activity.ParentSpanId.ToHexString(), + _ => null, + } ?? string.Empty; + } + } +} diff --git a/src/libraries/Microsoft.Extensions.Logging/src/LoggingBuilderExtensions.cs b/src/libraries/Microsoft.Extensions.Logging/src/LoggingBuilderExtensions.cs index 132e12f5fc363..19524c54c0ef5 100644 --- a/src/libraries/Microsoft.Extensions.Logging/src/LoggingBuilderExtensions.cs +++ b/src/libraries/Microsoft.Extensions.Logging/src/LoggingBuilderExtensions.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using System; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; using Microsoft.Extensions.Options; @@ -48,5 +49,17 @@ public static ILoggingBuilder ClearProviders(this ILoggingBuilder builder) builder.Services.RemoveAll(); return builder; } + + /// + /// Configure the with the . + /// + /// The to be configured with + /// The action used to configure the logger factory + /// The so that additional calls can be chained. + public static ILoggingBuilder Configure(this ILoggingBuilder builder, Action action) + { + builder.Services.Configure(action); + return builder; + } } } diff --git a/src/libraries/Microsoft.Extensions.Logging/src/Microsoft.Extensions.Logging.csproj b/src/libraries/Microsoft.Extensions.Logging/src/Microsoft.Extensions.Logging.csproj index c8a03b2300a2c..6684f9fd73f26 100644 --- a/src/libraries/Microsoft.Extensions.Logging/src/Microsoft.Extensions.Logging.csproj +++ b/src/libraries/Microsoft.Extensions.Logging/src/Microsoft.Extensions.Logging.csproj @@ -34,4 +34,8 @@ + + + + diff --git a/src/libraries/Microsoft.Extensions.Logging/tests/Common/ConsoleLoggerTest.cs b/src/libraries/Microsoft.Extensions.Logging/tests/Common/ConsoleLoggerTest.cs index 8c8786ca49461..cb185d9aafd34 100644 --- a/src/libraries/Microsoft.Extensions.Logging/tests/Common/ConsoleLoggerTest.cs +++ b/src/libraries/Microsoft.Extensions.Logging/tests/Common/ConsoleLoggerTest.cs @@ -3,8 +3,14 @@ // See the LICENSE file in the project root for more information. using System; +using System.IO; +using System.Threading; +using System.Globalization; +using System.Text; +using System.Diagnostics; using System.Collections.Generic; using System.Linq; +using Microsoft.DotNet.RemoteExecutor; using System.Text.RegularExpressions; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; @@ -1170,6 +1176,82 @@ public void ConsoleLoggerOptions_IncludeScopes_IsReadFromLoggingConfiguration() Assert.NotNull(logger.ScopeProvider); } + [Fact] + public void TestActivityIds() + { + RemoteExecutor.Invoke(() => + { + string activity1String; + string activity2String; + + StringWriter output = new StringWriter(); + System.Console.SetOut(output); + var loggerFactory = LoggerFactory.Create(builder => + { + builder.AddConsole(o => { o.IncludeScopes = true; }); + + // Enable logging trace context info in the logging scopes. + builder.Configure(o => o.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId | ActivityTrackingOptions.ParentId); + }); + + var logger = loggerFactory.CreateLogger(); + using (logger.BeginScope(new { Scope1 = 1 })) + { + logger.LogInformation("Inside Scope 1 & No Activity Yet."); + + var activity1 = new Activity("MyActivity1"); + activity1.Start(); + + activity1String = string.Format(CultureInfo.InvariantCulture, "=> SpanId:{0}, TraceId:{1}, ParentId:{2}", + activity1.GetSpanId(), activity1.GetTraceId(), activity1.GetParentId()); + + logger.LogInformation("Inside Scope 1 with Activity 1."); + + using (logger.BeginScope(new { Scope2 = 2 })) + { + logger.LogInformation("Inside Scope 2 with Activity 1."); + var activity2 = new Activity("MyActivity2"); + activity2.Start(); + activity2String = string.Format(CultureInfo.InvariantCulture, "=> SpanId:{0}, TraceId:{1}, ParentId:{2}", + activity2.GetSpanId(), activity2.GetTraceId(), activity2.GetParentId()); + + logger.LogInformation("Inside Scope 2 with Activity 2."); + activity2.Stop(); + logger.LogInformation("Back to Scope 2 with Activity 1."); + } + + logger.LogInformation("Back to Scope 1 with Activity 1."); + + activity1.Stop(); + } + + // give chance for logs to be written. + Thread.Sleep(1000); + + string expectedOutput = + $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + + $" => {{ Scope1 = 1 }}{Environment.NewLine}" + + $" Inside Scope 1 & No Activity Yet.{Environment.NewLine}" + + $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + + $" {activity1String} => {{ Scope1 = 1 }}{Environment.NewLine}" + + $" Inside Scope 1 with Activity 1.{Environment.NewLine}" + + $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + + $" {activity1String} => {{ Scope1 = 1 }} => {{ Scope2 = 2 }}{Environment.NewLine}" + + $" Inside Scope 2 with Activity 1.{Environment.NewLine}" + + $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + + $" {activity2String} => {{ Scope1 = 1 }} => {{ Scope2 = 2 }}{Environment.NewLine}" + + $" Inside Scope 2 with Activity 2.{Environment.NewLine}" + + $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + + $" {activity1String} => {{ Scope1 = 1 }} => {{ Scope2 = 2 }}{Environment.NewLine}" + + $" Back to Scope 2 with Activity 1.{Environment.NewLine}" + + $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + + $" {activity1String} => {{ Scope1 = 1 }}{Environment.NewLine}" + + $" Back to Scope 1 with Activity 1.{Environment.NewLine}"; + + Assert.Equal(expectedOutput, output.ToString()); + }).Dispose(); + } + public static TheoryData FormatsAndLevels { get @@ -1275,4 +1357,37 @@ public void Set(ConsoleLoggerOptions options) _onChange?.Invoke(options, ""); } } + + internal static class ActivityExtensions + { + public static string GetSpanId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.Id, + ActivityIdFormat.W3C => activity.SpanId.ToHexString(), + _ => null, + } ?? string.Empty; + } + + public static string GetTraceId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.RootId, + ActivityIdFormat.W3C => activity.TraceId.ToHexString(), + _ => null, + } ?? string.Empty; + } + + public static string GetParentId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.ParentId, + ActivityIdFormat.W3C => activity.ParentSpanId.ToHexString(), + _ => null, + } ?? string.Empty; + } + } } diff --git a/src/libraries/Microsoft.Extensions.Logging/tests/Common/Microsoft.Extensions.Logging.Tests.csproj b/src/libraries/Microsoft.Extensions.Logging/tests/Common/Microsoft.Extensions.Logging.Tests.csproj index cec257df2ecaa..b91523855ef11 100644 --- a/src/libraries/Microsoft.Extensions.Logging/tests/Common/Microsoft.Extensions.Logging.Tests.csproj +++ b/src/libraries/Microsoft.Extensions.Logging/tests/Common/Microsoft.Extensions.Logging.Tests.csproj @@ -3,6 +3,7 @@ $(NetCoreAppCurrent);$(NetFrameworkCurrent) true + true From d1a5f05942fc119b7a5eaa3967e30038cc11978c Mon Sep 17 00:00:00 2001 From: Tarek Mahmoud Sayed Date: Wed, 27 May 2020 15:20:17 -0700 Subject: [PATCH 2/5] Fix name casing --- .../src/Microsoft.Extensions.Logging.csproj | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libraries/Microsoft.Extensions.Logging/src/Microsoft.Extensions.Logging.csproj b/src/libraries/Microsoft.Extensions.Logging/src/Microsoft.Extensions.Logging.csproj index 6684f9fd73f26..4394be72056b2 100644 --- a/src/libraries/Microsoft.Extensions.Logging/src/Microsoft.Extensions.Logging.csproj +++ b/src/libraries/Microsoft.Extensions.Logging/src/Microsoft.Extensions.Logging.csproj @@ -35,7 +35,7 @@ - + From b7b7a94eb004c5d855ab3e71f2053caf7e62614b Mon Sep 17 00:00:00 2001 From: Tarek Mahmoud Sayed Date: Wed, 27 May 2020 19:49:26 -0700 Subject: [PATCH 3/5] Address the feedback --- .../tests/Common/ConsoleLoggerTest.cs | 115 ------------------ .../tests/Common/LoggerFactoryTest.cs | 74 +++++++++++ .../Microsoft.Extensions.Logging.Tests.csproj | 1 - 3 files changed, 74 insertions(+), 116 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Logging/tests/Common/ConsoleLoggerTest.cs b/src/libraries/Microsoft.Extensions.Logging/tests/Common/ConsoleLoggerTest.cs index cb185d9aafd34..8c8786ca49461 100644 --- a/src/libraries/Microsoft.Extensions.Logging/tests/Common/ConsoleLoggerTest.cs +++ b/src/libraries/Microsoft.Extensions.Logging/tests/Common/ConsoleLoggerTest.cs @@ -3,14 +3,8 @@ // See the LICENSE file in the project root for more information. using System; -using System.IO; -using System.Threading; -using System.Globalization; -using System.Text; -using System.Diagnostics; using System.Collections.Generic; using System.Linq; -using Microsoft.DotNet.RemoteExecutor; using System.Text.RegularExpressions; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; @@ -1176,82 +1170,6 @@ public void ConsoleLoggerOptions_IncludeScopes_IsReadFromLoggingConfiguration() Assert.NotNull(logger.ScopeProvider); } - [Fact] - public void TestActivityIds() - { - RemoteExecutor.Invoke(() => - { - string activity1String; - string activity2String; - - StringWriter output = new StringWriter(); - System.Console.SetOut(output); - var loggerFactory = LoggerFactory.Create(builder => - { - builder.AddConsole(o => { o.IncludeScopes = true; }); - - // Enable logging trace context info in the logging scopes. - builder.Configure(o => o.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId | ActivityTrackingOptions.ParentId); - }); - - var logger = loggerFactory.CreateLogger(); - using (logger.BeginScope(new { Scope1 = 1 })) - { - logger.LogInformation("Inside Scope 1 & No Activity Yet."); - - var activity1 = new Activity("MyActivity1"); - activity1.Start(); - - activity1String = string.Format(CultureInfo.InvariantCulture, "=> SpanId:{0}, TraceId:{1}, ParentId:{2}", - activity1.GetSpanId(), activity1.GetTraceId(), activity1.GetParentId()); - - logger.LogInformation("Inside Scope 1 with Activity 1."); - - using (logger.BeginScope(new { Scope2 = 2 })) - { - logger.LogInformation("Inside Scope 2 with Activity 1."); - var activity2 = new Activity("MyActivity2"); - activity2.Start(); - activity2String = string.Format(CultureInfo.InvariantCulture, "=> SpanId:{0}, TraceId:{1}, ParentId:{2}", - activity2.GetSpanId(), activity2.GetTraceId(), activity2.GetParentId()); - - logger.LogInformation("Inside Scope 2 with Activity 2."); - activity2.Stop(); - logger.LogInformation("Back to Scope 2 with Activity 1."); - } - - logger.LogInformation("Back to Scope 1 with Activity 1."); - - activity1.Stop(); - } - - // give chance for logs to be written. - Thread.Sleep(1000); - - string expectedOutput = - $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + - $" => {{ Scope1 = 1 }}{Environment.NewLine}" + - $" Inside Scope 1 & No Activity Yet.{Environment.NewLine}" + - $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + - $" {activity1String} => {{ Scope1 = 1 }}{Environment.NewLine}" + - $" Inside Scope 1 with Activity 1.{Environment.NewLine}" + - $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + - $" {activity1String} => {{ Scope1 = 1 }} => {{ Scope2 = 2 }}{Environment.NewLine}" + - $" Inside Scope 2 with Activity 1.{Environment.NewLine}" + - $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + - $" {activity2String} => {{ Scope1 = 1 }} => {{ Scope2 = 2 }}{Environment.NewLine}" + - $" Inside Scope 2 with Activity 2.{Environment.NewLine}" + - $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + - $" {activity1String} => {{ Scope1 = 1 }} => {{ Scope2 = 2 }}{Environment.NewLine}" + - $" Back to Scope 2 with Activity 1.{Environment.NewLine}" + - $"info: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest[0]{Environment.NewLine}" + - $" {activity1String} => {{ Scope1 = 1 }}{Environment.NewLine}" + - $" Back to Scope 1 with Activity 1.{Environment.NewLine}"; - - Assert.Equal(expectedOutput, output.ToString()); - }).Dispose(); - } - public static TheoryData FormatsAndLevels { get @@ -1357,37 +1275,4 @@ public void Set(ConsoleLoggerOptions options) _onChange?.Invoke(options, ""); } } - - internal static class ActivityExtensions - { - public static string GetSpanId(this Activity activity) - { - return activity.IdFormat switch - { - ActivityIdFormat.Hierarchical => activity.Id, - ActivityIdFormat.W3C => activity.SpanId.ToHexString(), - _ => null, - } ?? string.Empty; - } - - public static string GetTraceId(this Activity activity) - { - return activity.IdFormat switch - { - ActivityIdFormat.Hierarchical => activity.RootId, - ActivityIdFormat.W3C => activity.TraceId.ToHexString(), - _ => null, - } ?? string.Empty; - } - - public static string GetParentId(this Activity activity) - { - return activity.IdFormat switch - { - ActivityIdFormat.Hierarchical => activity.ParentId, - ActivityIdFormat.W3C => activity.ParentSpanId.ToHexString(), - _ => null, - } ?? string.Empty; - } - } } diff --git a/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs b/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs index 1cdae470f0efc..4005905b4bd24 100644 --- a/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs +++ b/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs @@ -3,6 +3,8 @@ // See the LICENSE file in the project root for more information. using System; +using System.Globalization; +using System.Diagnostics; using System.Collections.Generic; using Microsoft.Extensions.DependencyInjection; using Moq; @@ -92,6 +94,45 @@ public void Dispose_ThrowException_SwallowsException() .Verify(p => p.Dispose(), Times.Once()); } + [Fact] + public void TestActivityIds() + { + var loggerProvider = new ExternalScopeLoggerProvider(); + + var loggerFactory = LoggerFactory.Create(builder => + { + builder + .Configure(o => o.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId | ActivityTrackingOptions.ParentId) + .AddProvider(loggerProvider); + }); + + var logger = loggerFactory.CreateLogger("Logger"); + + Activity a = new Activity("ScopeActivity"); + a.Start(); + string activity1String = string.Format(CultureInfo.InvariantCulture, "SpanId:{0}, TraceId:{1}, ParentId:{2}", a.GetSpanId(), a.GetTraceId(), a.GetParentId()); + string activity2String; + + using (logger.BeginScope("Scope 1")) + { + logger.LogInformation("Message 1"); + Activity b = new Activity("ScopeActivity"); + b.Start(); + activity2String = string.Format(CultureInfo.InvariantCulture, "SpanId:{0}, TraceId:{1}, ParentId:{2}", b.GetSpanId(), b.GetTraceId(), b.GetParentId()); + + using (logger.BeginScope("Scope 2")) + { + logger.LogInformation("Message 2"); + } + b.Stop(); + } + + a.Stop(); + + Assert.Equal(activity1String, loggerProvider.LogText[1]); + Assert.Equal(activity2String, loggerProvider.LogText[4]); + } + [Fact] public void CallsSetScopeProvider_OnSupportedProviders() { @@ -261,4 +302,37 @@ public IDisposable BeginScope(TState state) } } } + + internal static class ActivityExtensions + { + public static string GetSpanId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.Id, + ActivityIdFormat.W3C => activity.SpanId.ToHexString(), + _ => null, + } ?? string.Empty; + } + + public static string GetTraceId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.RootId, + ActivityIdFormat.W3C => activity.TraceId.ToHexString(), + _ => null, + } ?? string.Empty; + } + + public static string GetParentId(this Activity activity) + { + return activity.IdFormat switch + { + ActivityIdFormat.Hierarchical => activity.ParentId, + ActivityIdFormat.W3C => activity.ParentSpanId.ToHexString(), + _ => null, + } ?? string.Empty; + } + } } diff --git a/src/libraries/Microsoft.Extensions.Logging/tests/Common/Microsoft.Extensions.Logging.Tests.csproj b/src/libraries/Microsoft.Extensions.Logging/tests/Common/Microsoft.Extensions.Logging.Tests.csproj index b91523855ef11..cec257df2ecaa 100644 --- a/src/libraries/Microsoft.Extensions.Logging/tests/Common/Microsoft.Extensions.Logging.Tests.csproj +++ b/src/libraries/Microsoft.Extensions.Logging/tests/Common/Microsoft.Extensions.Logging.Tests.csproj @@ -3,7 +3,6 @@ $(NetCoreAppCurrent);$(NetFrameworkCurrent) true - true From 6064146221ad7b8e780751dcc9397accbd8ee67d Mon Sep 17 00:00:00 2001 From: Tarek Mahmoud Sayed Date: Thu, 28 May 2020 16:38:51 -0700 Subject: [PATCH 4/5] Address the feedback --- .../src/LoggerFactoryScopeProvider.cs | 90 +++++++++---------- .../tests/Common/LoggerFactoryTest.cs | 77 ++++++++++++++-- 2 files changed, 115 insertions(+), 52 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs index 86fba14b14e74..e837bf4ff21ab 100644 --- a/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs +++ b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs @@ -97,79 +97,77 @@ public void Dispose() private class ActivityLogScope : IReadOnlyList> { - private readonly Activity _activity; - private readonly ActivityTrackingOptions _activityTrackingOption; - private string _cachedToString; + private const int MaxItems = 5; + private KeyValuePair [] _items = new KeyValuePair[MaxItems]; - public int Count + public ActivityLogScope(Activity activity, ActivityTrackingOptions activityTrackingOption) { - get + Debug.Assert(activity != null); + Debug.Assert(activityTrackingOption != ActivityTrackingOptions.None); + + int count = 0; + if ((activityTrackingOption & ActivityTrackingOptions.SpanId) != 0) + { + _items[count++] = new KeyValuePair("SpanId", activity.GetSpanId()); + } + + if ((activityTrackingOption & ActivityTrackingOptions.TraceId) != 0) + { + _items[count++] = new KeyValuePair("TraceId", activity.GetTraceId()); + } + + if ((activityTrackingOption & ActivityTrackingOptions.ParentId) != 0) + { + _items[count++] = new KeyValuePair("ParentId", activity.GetParentId()); + } + + if ((activityTrackingOption & ActivityTrackingOptions.TraceState) != 0) + { + _items[count++] = new KeyValuePair("TraceState", activity.TraceStateString); + } + + if ((activityTrackingOption & ActivityTrackingOptions.TraceFlags) != 0) { - return 3; + _items[count++] = new KeyValuePair("TraceFlags", activity.ActivityTraceFlags); } + + Count = count; } + public int Count { get; } + public KeyValuePair this[int index] { get { - if (index == 0) - { - return new KeyValuePair("SpanId", _activity.GetSpanId()); - } - else if (index == 1) - { - return new KeyValuePair("TraceId", _activity.GetTraceId()); - } - else if (index == 2) + if (index >= Count) { - return new KeyValuePair("ParentId", _activity.GetParentId()); + throw new ArgumentOutOfRangeException(nameof(index)); } - throw new ArgumentOutOfRangeException(nameof(index)); + return _items[index]; } } - public ActivityLogScope(Activity activity, ActivityTrackingOptions activityTrackingOption) - { - Debug.Assert(activityTrackingOption != ActivityTrackingOptions.None); - _activityTrackingOption = activityTrackingOption; - _activity = activity; - } - public override string ToString() { if (_cachedToString == null) { StringBuilder sb = new StringBuilder(); - if ((_activityTrackingOption & ActivityTrackingOptions.SpanId) != 0) - { - sb.Append($"SpanId:{_activity.GetSpanId()}"); - } - if ((_activityTrackingOption & ActivityTrackingOptions.TraceId) != 0) - { - sb.Append(sb.Length > 0 ? $", TraceId:{_activity.GetTraceId()}" : $"TraceId:{_activity.GetTraceId()}"); - } - - if ((_activityTrackingOption & ActivityTrackingOptions.ParentId) != 0) - { - sb.Append(sb.Length > 0 ? $", ParentId:{_activity.GetParentId()}" : $"TraceId:{_activity.GetParentId()}"); - } + sb.Append(_items[0].Key); + sb.Append(':'); + sb.Append(_items[0].Value); - if ((_activityTrackingOption & ActivityTrackingOptions.TraceFlags) != 0) + for (int i = 1; i < Count; i++) { - sb.Append(sb.Length > 0 ? $", TraceFlags:{_activity.ActivityTraceFlags}" : $"TraceFlags:{_activity.ActivityTraceFlags}"); + sb.Append(", "); + sb.Append(_items[i].Key); + sb.Append(':'); + sb.Append(_items[i].Value); } - - if ((_activityTrackingOption & ActivityTrackingOptions.TraceState) != 0 && _activity.TraceStateString != null) - { - sb.Append(sb.Length > 0 ? $", TraceState:{_activity.TraceStateString}" : $"TraceState:{_activity.TraceStateString}"); - } - _cachedToString = sb.ToString(); - } return _cachedToString; diff --git a/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs b/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs index 4005905b4bd24..f5c40bee51af1 100644 --- a/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs +++ b/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs @@ -3,6 +3,7 @@ // See the LICENSE file in the project root for more information. using System; +using System.Text; using System.Globalization; using System.Diagnostics; using System.Collections.Generic; @@ -94,15 +95,80 @@ public void Dispose_ThrowException_SwallowsException() .Verify(p => p.Dispose(), Times.Once()); } - [Fact] - public void TestActivityIds() + private static string GetActivityLogString(ActivityTrackingOptions options) + { + Activity activity = Activity.Current; + if (activity == null) + { + return string.Empty; + } + + StringBuilder sb = new StringBuilder(); + if ((options & ActivityTrackingOptions.SpanId) != 0) + { + sb.Append($"SpanId:{activity.GetSpanId()}"); + } + + if ((options & ActivityTrackingOptions.TraceId) != 0) + { + sb.Append(sb.Length > 0 ? $", TraceId:{activity.GetTraceId()}" : $"TraceId:{activity.GetTraceId()}"); + } + + if ((options & ActivityTrackingOptions.ParentId) != 0) + { + sb.Append(sb.Length > 0 ? $", ParentId:{activity.GetParentId()}" : $"ParentId:{activity.GetParentId()}"); + } + + if ((options & ActivityTrackingOptions.TraceState) != 0) + { + sb.Append(sb.Length > 0 ? $", TraceState:{activity.TraceStateString}" : $"TraceState:{activity.TraceStateString}"); + } + + if ((options & ActivityTrackingOptions.TraceFlags) != 0) + { + sb.Append(sb.Length > 0 ? $", TraceFlags:{activity.ActivityTraceFlags}" : $"TraceFlags:{activity.ActivityTraceFlags}"); + } + + return sb.ToString(); + } + + [Theory] + [InlineData(ActivityTrackingOptions.SpanId)] + [InlineData(ActivityTrackingOptions.TraceId)] + [InlineData(ActivityTrackingOptions.ParentId)] + [InlineData(ActivityTrackingOptions.TraceState)] + [InlineData(ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceId)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.ParentId)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceState)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.TraceId | ActivityTrackingOptions.ParentId)] + [InlineData(ActivityTrackingOptions.TraceId | ActivityTrackingOptions.TraceState)] + [InlineData(ActivityTrackingOptions.TraceId | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.ParentId | ActivityTrackingOptions.TraceState)] + [InlineData(ActivityTrackingOptions.ParentId | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.TraceState | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceId | ActivityTrackingOptions.ParentId)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceId | ActivityTrackingOptions.TraceState)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceId | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.ParentId | ActivityTrackingOptions.TraceState)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.ParentId | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceState | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.TraceId | ActivityTrackingOptions.ParentId | ActivityTrackingOptions.TraceState)] + [InlineData(ActivityTrackingOptions.TraceId | ActivityTrackingOptions.ParentId | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.TraceId | ActivityTrackingOptions.TraceState | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceId | ActivityTrackingOptions.ParentId | ActivityTrackingOptions.TraceState)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceId | ActivityTrackingOptions.ParentId | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.TraceId | ActivityTrackingOptions.ParentId | ActivityTrackingOptions.TraceState | ActivityTrackingOptions.TraceFlags)] + [InlineData(ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceId | ActivityTrackingOptions.ParentId | ActivityTrackingOptions.TraceState | ActivityTrackingOptions.TraceFlags)] + public void TestActivityIds(ActivityTrackingOptions options) { var loggerProvider = new ExternalScopeLoggerProvider(); var loggerFactory = LoggerFactory.Create(builder => { builder - .Configure(o => o.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId | ActivityTrackingOptions.ParentId) + .Configure(o => o.ActivityTrackingOptions = options) .AddProvider(loggerProvider); }); @@ -110,7 +176,7 @@ public void TestActivityIds() Activity a = new Activity("ScopeActivity"); a.Start(); - string activity1String = string.Format(CultureInfo.InvariantCulture, "SpanId:{0}, TraceId:{1}, ParentId:{2}", a.GetSpanId(), a.GetTraceId(), a.GetParentId()); + string activity1String = GetActivityLogString(options); string activity2String; using (logger.BeginScope("Scope 1")) @@ -118,7 +184,7 @@ public void TestActivityIds() logger.LogInformation("Message 1"); Activity b = new Activity("ScopeActivity"); b.Start(); - activity2String = string.Format(CultureInfo.InvariantCulture, "SpanId:{0}, TraceId:{1}, ParentId:{2}", b.GetSpanId(), b.GetTraceId(), b.GetParentId()); + activity2String = GetActivityLogString(options); using (logger.BeginScope("Scope 2")) { @@ -126,7 +192,6 @@ public void TestActivityIds() } b.Stop(); } - a.Stop(); Assert.Equal(activity1String, loggerProvider.LogText[1]); From 6fb84564279bc13436e2b0f8e4c3eaf0cf6746d6 Mon Sep 17 00:00:00 2001 From: Tarek Mahmoud Sayed Date: Fri, 29 May 2020 13:37:42 -0700 Subject: [PATCH 5/5] Validate ActivityTrackingOptions input and add test --- .../src/LoggerFactory.cs | 8 ++ .../src/LoggerFactoryScopeProvider.cs | 2 +- .../src/Resources/Strings.resx | 122 ++++++++++++++++++ .../tests/Common/LoggerFactoryTest.cs | 8 ++ 4 files changed, 139 insertions(+), 1 deletion(-) create mode 100644 src/libraries/Microsoft.Extensions.Logging/src/Resources/Strings.resx diff --git a/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs index 903a8bf82c5ff..99b44aa87cb5b 100644 --- a/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs +++ b/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs @@ -69,6 +69,14 @@ public LoggerFactory(IEnumerable providers, IOptionsMonitor _currentScope = new AsyncLocal(); - private ActivityTrackingOptions _activityTrackingOption; + private readonly ActivityTrackingOptions _activityTrackingOption; public LoggerFactoryScopeProvider(ActivityTrackingOptions activityTrackingOption) => _activityTrackingOption = activityTrackingOption; diff --git a/src/libraries/Microsoft.Extensions.Logging/src/Resources/Strings.resx b/src/libraries/Microsoft.Extensions.Logging/src/Resources/Strings.resx new file mode 100644 index 0000000000000..2e85d31c8ac0d --- /dev/null +++ b/src/libraries/Microsoft.Extensions.Logging/src/Resources/Strings.resx @@ -0,0 +1,122 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + text/microsoft-resx + + + 2.0 + + + System.Resources.ResXResourceReader, System.Windows.Forms, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089 + + + System.Resources.ResXResourceWriter, System.Windows.Forms, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089 + + + {0} is invalid ActivityTrackingOptions value. + + diff --git a/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs b/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs index f5c40bee51af1..21d0f04f4b24d 100644 --- a/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs +++ b/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs @@ -198,6 +198,14 @@ public void TestActivityIds(ActivityTrackingOptions options) Assert.Equal(activity2String, loggerProvider.LogText[4]); } + [Fact] + public void TestInvalidActivityTrackingOptions() + { + Assert.Throws(() => + LoggerFactory.Create(builder => { builder.Configure(o => o.ActivityTrackingOptions = (ActivityTrackingOptions) 0xFF00);}) + ); + } + [Fact] public void CallsSetScopeProvider_OnSupportedProviders() {