From cd85e8d7e93a451aba56482402d7e00d671b835d Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Wed, 25 Jul 2018 19:26:40 +0200 Subject: [PATCH 01/13] BeginScope with support for custom objects that are not marked as serializable (Ex. ActionLogScope) --- .../Logging/NLogLogger.cs | 47 ++++++++-- .../NLog.Extensions.Logging.csproj | 5 +- test/CustomBeginScopeTest.cs | 91 +++++++++++++++++++ 3 files changed, 131 insertions(+), 12 deletions(-) create mode 100644 test/CustomBeginScopeTest.cs diff --git a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs index dac85c46..1ee776aa 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs @@ -372,7 +372,7 @@ private class ScopeProperties : IDisposable /// List Properties => _properties ?? (_properties = new List()); - public static ScopeProperties CreateFromState(IList> messageProperties) + public static ScopeProperties CreateFromState(IReadOnlyList> messageProperties) { ScopeProperties scope = new ScopeProperties(); @@ -382,10 +382,31 @@ public static ScopeProperties CreateFromState(IList scope.AddProperty(property.Key, property.Value); } - scope.AddDispose(NestedDiagnosticsLogicalContext.Push(messageProperties)); + scope.AddDispose(CreateDiagnosticLogicalContext(messageProperties)); return scope; } + public static IDisposable CreateDiagnosticLogicalContext(T state) + { + try + { +#if NETSTANDARD + return NestedDiagnosticsLogicalContext.Push(state); // AsyncLocal has no requirement to be Serializable +#else + // TODO Add support for Net46 in NLog (AsyncLocal), then we only have to do this check for legacy Net451 (CallContext) + if (state?.GetType().IsSerializable ?? true) + return NestedDiagnosticsLogicalContext.Push(state); + else + return NestedDiagnosticsLogicalContext.Push(state.ToString()); // Support ViewComponentLogScope, ActionLogScope and others +#endif + } + catch (Exception ex) + { + InternalLogger.Debug(ex, "Exception in BeginScope push NestedDiagnosticsLogicalContext"); + return null; + } + } + public static bool TryCreateExtractor(ConcurrentDictionary, Func>> stateExractor, T property, out KeyValuePair, Func> keyValueExtractor) { Type propertyType = property.GetType(); @@ -417,7 +438,7 @@ public static bool TryCreateExtractor(ConcurrentDictionary(TState state, Concurr } if (scope != null) - scope.AddDispose(NestedDiagnosticsLogicalContext.Push(state)); + scope.AddDispose(CreateDiagnosticLogicalContext(state)); return scope; } @@ -474,13 +495,14 @@ private static void AddKeyValueProperty(ScopeProperties scope, KeyValuePair(TState state) if (_options.CaptureMessageProperties) { - if (state is IList> contextProperties) + if (state is IReadOnlyList> contextProperties) { return ScopeProperties.CreateFromState(contextProperties); } - else if (!(state is string)) + + if (!(state is string)) { var scope = ScopeProperties.CreateFromStateExtractor(state, _scopeStateExtractors); if (scope != null) return scope; } + else + { + return NestedDiagnosticsLogicalContext.Push(state); + } } - return NestedDiagnosticsLogicalContext.Push(state); + return NestedDiagnosticsLogicalContext.Push(ScopeProperties.CreateDiagnosticLogicalContext(state)); } } } diff --git a/src/NLog.Extensions.Logging/NLog.Extensions.Logging.csproj b/src/NLog.Extensions.Logging/NLog.Extensions.Logging.csproj index 57c7acdd..e401e8d6 100644 --- a/src/NLog.Extensions.Logging/NLog.Extensions.Logging.csproj +++ b/src/NLog.Extensions.Logging/NLog.Extensions.Logging.csproj @@ -42,15 +42,16 @@ For ASP.NET Core, use NLog.Web.AspNetCore: https://www.nuget.org/packages/NLog.W NLog.Extensions.Logging for NetStandard 1.3 1.6.0 - $(DefineConstants);NETCORE1_0 + $(DefineConstants);NETCORE1_0;NETSTANDARD NLog.Extensions.Logging for NetStandard 1.5 1.6.0 - $(DefineConstants);NETCORE1_0 + $(DefineConstants);NETCORE1_0;NETSTANDARD NLog.Extensions.Logging for NetStandard 2.0 + $(DefineConstants);NETSTANDARD diff --git a/test/CustomBeginScopeTest.cs b/test/CustomBeginScopeTest.cs new file mode 100644 index 00000000..91534c33 --- /dev/null +++ b/test/CustomBeginScopeTest.cs @@ -0,0 +1,91 @@ +using System; +using System.Collections; +using System.Collections.Generic; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace NLog.Extensions.Logging.Tests +{ + public class CustomBeginScopeTest : NLogTestBase + { + [Fact] + public void TestCallSiteSayHello() + { + var runner = GetRunner(); + var target = new NLog.Targets.MemoryTarget() { Layout = "${message} ${ndlc}" }; + NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(target); + runner.SayHello(); + Assert.Single(target.Logs); + Assert.Contains("Hello World", target.Logs[0]); + } + + + public class CustomBeginScopeTestRunner + { + private readonly ILogger _logger; + + public CustomBeginScopeTestRunner(ILogger logger) + { + _logger = logger; + } + + public void SayHello() + { + using (_logger.BeginScope(new ActionLogScope("World"))) + { + _logger.LogInformation("Hello"); + } + } + } + + private class ActionLogScope : IReadOnlyList> + { + private readonly string _action; + + public ActionLogScope(string action) + { + if (action == null) + { + throw new ArgumentNullException(nameof(action)); + } + + _action = action; + } + + public KeyValuePair this[int index] + { + get + { + if (index == 0) + { + return new KeyValuePair("ActionId", _action); + } + throw new IndexOutOfRangeException(nameof(index)); + } + } + + public int Count => 1; + + public IEnumerator> GetEnumerator() + { + for (var i = 0; i < Count; ++i) + { + yield return this[i]; + } + } + + public override string ToString() + { + // We don't include the _action.Id here because it's just an opaque guid, and if + // you have text logging, you can already use the requestId for correlation. + return _action; + } + + IEnumerator IEnumerable.GetEnumerator() + { + return GetEnumerator(); + } + } + } +} From 41a25a17ce58835bc0e164bddf6eda15a92fdd52 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Wed, 25 Jul 2018 21:46:59 +0200 Subject: [PATCH 02/13] Introduced NLogBeginScopeParser that provides caching of property-reflection across all NLogLogger-objects (Reduce allocation and better cache reuse). --- examples/NetCore2/ConsoleExample/Program.cs | 15 +- .../Extensions/ConfigureExtensions.cs | 10 +- .../Logging/NLogBeginScopeParser.cs | 214 ++++++++++++++++++ .../Logging/NLogLogger.cs | 211 +---------------- .../Logging/NLogLoggerProvider.cs | 6 +- 5 files changed, 235 insertions(+), 221 deletions(-) create mode 100644 src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs diff --git a/examples/NetCore2/ConsoleExample/Program.cs b/examples/NetCore2/ConsoleExample/Program.cs index c85032c0..5f4144ee 100644 --- a/examples/NetCore2/ConsoleExample/Program.cs +++ b/examples/NetCore2/ConsoleExample/Program.cs @@ -12,13 +12,14 @@ static void Main(string[] args) var logger = NLog.LogManager.LoadConfiguration("nlog.config").GetCurrentClassLogger(); try { - var servicesProvider = BuildDi(); - var runner = servicesProvider.GetRequiredService(); + using (var servicesProvider = BuildDi()) + { + var runner = servicesProvider.GetRequiredService(); + runner.DoAction("Action1"); - runner.DoAction("Action1"); - - Console.WriteLine("Press ANY key to exit"); - Console.ReadLine(); + Console.WriteLine("Press ANY key to exit"); + Console.ReadLine(); + } } catch (Exception ex) { @@ -34,7 +35,7 @@ static void Main(string[] args) } - private static IServiceProvider BuildDi() + private static ServiceProvider BuildDi() { var services = new ServiceCollection(); diff --git a/src/NLog.Extensions.Logging/Extensions/ConfigureExtensions.cs b/src/NLog.Extensions.Logging/Extensions/ConfigureExtensions.cs index fe41724c..5cc580c4 100644 --- a/src/NLog.Extensions.Logging/Extensions/ConfigureExtensions.cs +++ b/src/NLog.Extensions.Logging/Extensions/ConfigureExtensions.cs @@ -29,10 +29,7 @@ public static ILoggerFactory AddNLog(this ILoggerFactory factory) /// ILoggerFactory for chaining public static ILoggerFactory AddNLog(this ILoggerFactory factory, NLogProviderOptions options) { - using (var provider = new NLogLoggerProvider(options)) - { - factory.AddProvider(provider); - } + factory.AddProvider(new NLogLoggerProvider(options)); return factory; } @@ -55,10 +52,7 @@ public static ILoggingBuilder AddNLog(this ILoggingBuilder factory) /// ILoggerFactory for chaining public static ILoggingBuilder AddNLog(this ILoggingBuilder factory, NLogProviderOptions options) { - using (var provider = new NLogLoggerProvider(options)) - { - factory.AddProvider(provider); - } + factory.AddProvider(new NLogLoggerProvider(options)); return factory; } #endif diff --git a/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs b/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs new file mode 100644 index 00000000..24ad9e62 --- /dev/null +++ b/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs @@ -0,0 +1,214 @@ +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Reflection; +using NLog.Common; + +namespace NLog.Extensions.Logging +{ + /// + /// Converts Microsoft Extension Logging BeginScope into NLog NestedDiagnosticsLogicalContext + MappedDiagnosticsLogicalContext + /// + internal class NLogBeginScopeParser + { + private readonly NLogProviderOptions _options; + private readonly ConcurrentDictionary, Func>> _scopeStateExtractors = new ConcurrentDictionary, Func>>(); + + public NLogBeginScopeParser(NLogProviderOptions options) + { + _options = options ?? NLogProviderOptions.Default; + } + + public IDisposable ParseBeginScope(T state) + { + if (_options.CaptureMessageProperties) + { + if (state is IReadOnlyList> contextProperties) + { + return ScopeProperties.CreateFromState(contextProperties); + } + + if (!(state is string)) + { + var scope = ScopeProperties.CreateFromStateExtractor(state, _scopeStateExtractors); + if (scope != null) + return scope; + } + else + { + return NestedDiagnosticsLogicalContext.Push(state); + } + } + + return CreateDiagnosticLogicalContext(state); + } + + public static IDisposable CreateDiagnosticLogicalContext(T state) + { + try + { +#if NETSTANDARD + return NestedDiagnosticsLogicalContext.Push(state); // AsyncLocal has no requirement to be Serializable +#else + // TODO Add support for Net46 in NLog (AsyncLocal), then we only have to do this check for legacy Net451 (CallContext) + if (state?.GetType().IsSerializable ?? true) + return NestedDiagnosticsLogicalContext.Push(state); + else + return NestedDiagnosticsLogicalContext.Push(state.ToString()); // Support ViewComponentLogScope, ActionLogScope and others +#endif + } + catch (Exception ex) + { + InternalLogger.Debug(ex, "Exception in BeginScope push NestedDiagnosticsLogicalContext"); + return null; + } + } + + private class ScopeProperties : IDisposable + { + List _properties; + + /// + /// Properties, never null and lazy init + /// + List Properties => _properties ?? (_properties = new List()); + + public static ScopeProperties CreateFromState(IReadOnlyList> messageProperties) + { + ScopeProperties scope = new ScopeProperties(); + + for (int i = 0; i < messageProperties.Count; ++i) + { + var property = messageProperties[i]; + scope.AddProperty(property.Key, property.Value); + } + + scope.AddDispose(CreateDiagnosticLogicalContext(messageProperties)); + return scope; + } + + public static bool TryCreateExtractor(ConcurrentDictionary, Func>> stateExractor, T property, out KeyValuePair, Func> keyValueExtractor) + { + Type propertyType = property.GetType(); + + if (!stateExractor.TryGetValue(propertyType, out keyValueExtractor)) + { + try + { + var itemType = propertyType.GetTypeInfo(); + if (!itemType.IsGenericType || itemType.GetGenericTypeDefinition() != typeof(KeyValuePair<,>)) + return false; + + var keyPropertyInfo = itemType.GetDeclaredProperty("Key"); + var valuePropertyInfo = itemType.GetDeclaredProperty("Value"); + if (valuePropertyInfo == null || keyPropertyInfo == null) + return false; + + var keyValuePairObjParam = System.Linq.Expressions.Expression.Parameter(typeof(object), "pair"); + var keyValuePairTypeParam = System.Linq.Expressions.Expression.Convert(keyValuePairObjParam, propertyType); + + var propertyKeyAccess = System.Linq.Expressions.Expression.Property(keyValuePairTypeParam, keyPropertyInfo); + var propertyKeyAccessObj = System.Linq.Expressions.Expression.Convert(propertyKeyAccess, typeof(object)); + var propertyKeyLambda = System.Linq.Expressions.Expression.Lambda>(propertyKeyAccessObj, keyValuePairObjParam).Compile(); + + var propertyValueAccess = System.Linq.Expressions.Expression.Property(keyValuePairTypeParam, valuePropertyInfo); + var propertyValueLambda = System.Linq.Expressions.Expression.Lambda>(propertyValueAccess, keyValuePairObjParam).Compile(); + + keyValueExtractor = new KeyValuePair, Func>(propertyKeyLambda, propertyValueLambda); + } + catch (Exception ex) + { + InternalLogger.Debug(ex, "Exception in BeginScope create property extractor"); + } + finally + { + stateExractor[propertyType] = keyValueExtractor; + } + } + + return keyValueExtractor.Key != null; + } + + public static IDisposable CreateFromStateExtractor(TState state, ConcurrentDictionary, Func>> stateExractor) + { + ScopeProperties scope = null; + var keyValueExtractor = default(KeyValuePair, Func>); + if (state is System.Collections.IEnumerable messageProperties) + { + foreach (var property in messageProperties) + { + if (property == null) + return null; + + if (scope == null) + { + if (!TryCreateExtractor(stateExractor, property, out keyValueExtractor)) + return null; + + scope = new ScopeProperties(); + } + + AddKeyValueProperty(scope, keyValueExtractor, property); + } + } + else + { + if (!TryCreateExtractor(stateExractor, state, out keyValueExtractor)) + return null; + + scope = new ScopeProperties(); + AddKeyValueProperty(scope, keyValueExtractor, state); + } + + if (scope != null) + scope.AddDispose(CreateDiagnosticLogicalContext(state)); + return scope; + } + + private static void AddKeyValueProperty(ScopeProperties scope, KeyValuePair, Func> keyValueExtractor, object property) + { + try + { + var propertyKey = keyValueExtractor.Key.Invoke(property); + var propertyValue = keyValueExtractor.Value.Invoke(property); + scope.AddProperty(propertyKey?.ToString() ?? string.Empty, propertyValue); + } + catch (Exception ex) + { + InternalLogger.Debug(ex, "Exception in BeginScope add property"); + } + } + + public void AddDispose(IDisposable disposable) + { + if (disposable != null) + Properties.Add(disposable); + } + + public void AddProperty(string key, object value) + { + AddDispose(MappedDiagnosticsLogicalContext.SetScoped(key, value)); + } + + public void Dispose() + { + var properties = _properties; + if (properties != null) + { + _properties = null; + foreach (var property in properties) + { + try + { + property.Dispose(); + } + catch (Exception ex) + { + InternalLogger.Debug(ex, "Exception in BeginScope dispose property {0}", property); + } + } + } + } + } + } +} diff --git a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs index 1ee776aa..7f0eeec5 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs @@ -13,20 +13,20 @@ namespace NLog.Extensions.Logging /// internal class NLogLogger : Microsoft.Extensions.Logging.ILogger { - private readonly ConcurrentDictionary, Func>> _scopeStateExtractors = new ConcurrentDictionary, Func>>(); - private readonly Logger _logger; private readonly NLogProviderOptions _options; + private readonly NLogBeginScopeParser _beginScopeParser; internal const string OriginalFormatPropertyName = "{OriginalFormat}"; private static readonly object EmptyEventId = default(EventId); // Cache boxing of empty EventId-struct private static readonly object ZeroEventId = default(EventId).Id; // Cache boxing of zero EventId-Value private Tuple _eventIdPropertyNames; - public NLogLogger(Logger logger, NLogProviderOptions options) + public NLogLogger(Logger logger, NLogProviderOptions options, NLogBeginScopeParser beginScopeParser) { _logger = logger; _options = options ?? NLogProviderOptions.Default; + _beginScopeParser = beginScopeParser; } public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) @@ -363,191 +363,6 @@ private static LogLevel ConvertLogLevel(Microsoft.Extensions.Logging.LogLevel lo } } - private class ScopeProperties : IDisposable - { - List _properties; - - /// - /// Properties, never null and lazy init - /// - List Properties => _properties ?? (_properties = new List()); - - public static ScopeProperties CreateFromState(IReadOnlyList> messageProperties) - { - ScopeProperties scope = new ScopeProperties(); - - for (int i = 0; i < messageProperties.Count; ++i) - { - var property = messageProperties[i]; - scope.AddProperty(property.Key, property.Value); - } - - scope.AddDispose(CreateDiagnosticLogicalContext(messageProperties)); - return scope; - } - - public static IDisposable CreateDiagnosticLogicalContext(T state) - { - try - { -#if NETSTANDARD - return NestedDiagnosticsLogicalContext.Push(state); // AsyncLocal has no requirement to be Serializable -#else - // TODO Add support for Net46 in NLog (AsyncLocal), then we only have to do this check for legacy Net451 (CallContext) - if (state?.GetType().IsSerializable ?? true) - return NestedDiagnosticsLogicalContext.Push(state); - else - return NestedDiagnosticsLogicalContext.Push(state.ToString()); // Support ViewComponentLogScope, ActionLogScope and others -#endif - } - catch (Exception ex) - { - InternalLogger.Debug(ex, "Exception in BeginScope push NestedDiagnosticsLogicalContext"); - return null; - } - } - - public static bool TryCreateExtractor(ConcurrentDictionary, Func>> stateExractor, T property, out KeyValuePair, Func> keyValueExtractor) - { - Type propertyType = property.GetType(); - - if (!stateExractor.TryGetValue(propertyType, out keyValueExtractor)) - { - try - { - var itemType = propertyType.GetTypeInfo(); - if (!itemType.IsGenericType || itemType.GetGenericTypeDefinition() != typeof(KeyValuePair<,>)) - return false; - - var keyPropertyInfo = itemType.GetDeclaredProperty("Key"); - var valuePropertyInfo = itemType.GetDeclaredProperty("Value"); - if (valuePropertyInfo == null || keyPropertyInfo == null) - return false; - - var keyValuePairObjParam = System.Linq.Expressions.Expression.Parameter(typeof(object), "pair"); - var keyValuePairTypeParam = System.Linq.Expressions.Expression.Convert(keyValuePairObjParam, propertyType); - - var propertyKeyAccess = System.Linq.Expressions.Expression.Property(keyValuePairTypeParam, keyPropertyInfo); - var propertyKeyAccessObj = System.Linq.Expressions.Expression.Convert(propertyKeyAccess, typeof(object)); - var propertyKeyLambda = System.Linq.Expressions.Expression.Lambda>(propertyKeyAccessObj, keyValuePairObjParam).Compile(); - - var propertyValueAccess = System.Linq.Expressions.Expression.Property(keyValuePairTypeParam, valuePropertyInfo); - var propertyValueLambda = System.Linq.Expressions.Expression.Lambda>(propertyValueAccess, keyValuePairObjParam).Compile(); - - keyValueExtractor = new KeyValuePair, Func>(propertyKeyLambda, propertyValueLambda); - } - catch (Exception ex) - { - InternalLogger.Debug(ex, "Exception in BeginScope create property extractor"); - } - finally - { - stateExractor[propertyType] = keyValueExtractor; - } - } - - return keyValueExtractor.Key != null; - } - - public static IDisposable CreateFromStateExtractor(TState state, ConcurrentDictionary, Func>> stateExractor) - { - ScopeProperties scope = null; - var keyValueExtractor = default(KeyValuePair, Func>); - if (state is System.Collections.IEnumerable messageProperties) - { - foreach (var property in messageProperties) - { - if (property == null) - return null; - - if (scope == null) - { - if (!TryCreateExtractor(stateExractor, property, out keyValueExtractor)) - return null; - - scope = new ScopeProperties(); - } - - AddKeyValueProperty(scope, keyValueExtractor, property); - } - } - else - { - if (!TryCreateExtractor(stateExractor, state, out keyValueExtractor)) - return null; - - scope = new ScopeProperties(); - AddKeyValueProperty(scope, keyValueExtractor, state); - } - - if (scope != null) - scope.AddDispose(CreateDiagnosticLogicalContext(state)); - return scope; - } - - private static void AddKeyValueProperty(ScopeProperties scope, KeyValuePair, Func> keyValueExtractor, object property) - { - try - { - var propertyKey = keyValueExtractor.Key.Invoke(property); - var propertyValue = keyValueExtractor.Value.Invoke(property); - scope.AddProperty(propertyKey?.ToString() ?? string.Empty, propertyValue); - } - catch (Exception ex) - { - InternalLogger.Debug(ex, "Exception in BeginScope add property"); - } - } - - public void AddDispose(IDisposable disposable) - { - if (disposable != null) - Properties.Add(disposable); - } - - public void AddProperty(string key, object value) - { - AddDispose(new ScopeProperty(key, value)); - } - - public void Dispose() - { - var properties = _properties; - if (properties != null) - { - _properties = null; - foreach (var property in properties) - { - try - { - property.Dispose(); - } - catch (Exception ex) - { - InternalLogger.Debug(ex, "Exception in BeginScope dispose property {0}", property); - } - } - } - } - - class ScopeProperty : IDisposable - { - string _key; - - public ScopeProperty(string key, object value) - { - _key = key; - MappedDiagnosticsLogicalContext.Set(key, value); - } - - public void Dispose() - { - MappedDiagnosticsLogicalContext.Remove(_key); - } - } - - } - /// /// Begin a scope. Use in config with ${ndlc} /// @@ -560,26 +375,12 @@ public IDisposable BeginScope(TState state) throw new ArgumentNullException(nameof(state)); } - if (_options.CaptureMessageProperties) + if (_beginScopeParser != null) { - if (state is IReadOnlyList> contextProperties) - { - return ScopeProperties.CreateFromState(contextProperties); - } - - if (!(state is string)) - { - var scope = ScopeProperties.CreateFromStateExtractor(state, _scopeStateExtractors); - if (scope != null) - return scope; - } - else - { - return NestedDiagnosticsLogicalContext.Push(state); - } + return _beginScopeParser.ParseBeginScope(state); } - return NestedDiagnosticsLogicalContext.Push(ScopeProperties.CreateDiagnosticLogicalContext(state)); + return NLogBeginScopeParser.CreateDiagnosticLogicalContext(state); } } } diff --git a/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs b/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs index e3c3ffaf..2cf9143d 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs @@ -19,6 +19,7 @@ public class NLogLoggerProvider : Microsoft.Extensions.Logging.ILoggerProvider /// NLog options /// public NLogProviderOptions Options { get; set; } + private NLogBeginScopeParser _beginScopeParser; /// /// New provider with default options, see @@ -35,6 +36,7 @@ public NLogLoggerProvider() public NLogLoggerProvider(NLogProviderOptions options) { Options = options; + _beginScopeParser = new NLogBeginScopeParser(options); RegisterHiddenAssembliesForCallSite(); } @@ -45,7 +47,8 @@ public NLogLoggerProvider(NLogProviderOptions options) /// New Logger public Microsoft.Extensions.Logging.ILogger CreateLogger(string name) { - return new NLogLogger(LogManager.GetLogger(name), Options); + var beginScopeExtractor = (Options?.CaptureMessageProperties ?? true) ? (_beginScopeParser ?? System.Threading.Interlocked.CompareExchange(ref _beginScopeParser, new NLogBeginScopeParser(Options), null)) : null; + return new NLogLogger(LogManager.GetLogger(name), Options, beginScopeExtractor); } /// @@ -53,6 +56,7 @@ public Microsoft.Extensions.Logging.ILogger CreateLogger(string name) /// public void Dispose() { + LogManager.Flush(); } /// From 7f883c636f087d01d60689ab1e8854835902b14c Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Wed, 25 Jul 2018 22:33:31 +0200 Subject: [PATCH 03/13] Fixed Sonar Lint warnings --- src/NLog.Extensions.Logging/Logging/NLogLoggerFactory.cs | 2 +- .../Logging/NLogMessageParameterList.cs | 8 ++++---- .../Logging/NLogProviderOptions.cs | 2 +- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogLoggerFactory.cs b/src/NLog.Extensions.Logging/Logging/NLogLoggerFactory.cs index 56b38b66..ff11503b 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLoggerFactory.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLoggerFactory.cs @@ -9,7 +9,7 @@ namespace NLog.Extensions.Logging /// public class NLogLoggerFactory : ILoggerFactory { - private NLogLoggerProvider _provider; + private readonly NLogLoggerProvider _provider; /// /// New factory with default options diff --git a/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs b/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs index a21b49e0..16cc01fe 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs @@ -13,14 +13,14 @@ internal class NLogMessageParameterList : IList private readonly IReadOnlyList> _parameterList; public object OriginalMessage => _originalMessageIndex.HasValue ? _parameterList[_originalMessageIndex.Value].Value : null; - private int? _originalMessageIndex; + private readonly int? _originalMessageIndex; public bool HasComplexParameters => _hasMessageTemplateCapture || _isMixedPositional; - private bool _hasMessageTemplateCapture; - private bool _isMixedPositional; + private readonly bool _hasMessageTemplateCapture; + private readonly bool _isMixedPositional; public bool IsPositional => _isPositional; - private bool _isPositional; + private readonly bool _isPositional; public NLogMessageParameterList(IReadOnlyList> parameterList) { diff --git a/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs b/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs index 8c46f30a..07fa80ec 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs @@ -48,6 +48,6 @@ public NLogProviderOptions() /// /// Default options /// - internal static NLogProviderOptions Default = new NLogProviderOptions(); + internal static readonly NLogProviderOptions Default = new NLogProviderOptions(); } } From 28ac1933892468406b0f04c376e699f3957edbd5 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Wed, 25 Jul 2018 22:55:30 +0200 Subject: [PATCH 04/13] Added NLogProviderOptions.IncludeScopes to disable overhead of BeginScope --- .../Logging/NLogLogger.cs | 19 +++++++++++++++++++ .../Logging/NLogLoggerProvider.cs | 4 +++- .../Logging/NLogProviderOptions.cs | 6 ++++++ test/CustomBeginScopeTest.cs | 18 +++++++++++++++--- 4 files changed, 43 insertions(+), 4 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs index 7f0eeec5..f8c95850 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs @@ -370,6 +370,11 @@ private static LogLevel ConvertLogLevel(Microsoft.Extensions.Logging.LogLevel lo /// public IDisposable BeginScope(TState state) { + if (!_options.IncludeScopes) + { + return NullScope.Instance; + } + if (state == null) { throw new ArgumentNullException(nameof(state)); @@ -382,5 +387,19 @@ public IDisposable BeginScope(TState state) return NLogBeginScopeParser.CreateDiagnosticLogicalContext(state); } + + private class NullScope : IDisposable + { + public static NullScope Instance { get; } = new NullScope(); + + private NullScope() + { + } + + /// + public void Dispose() + { + } + } } } diff --git a/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs b/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs index 2cf9143d..ffe7bce8 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs @@ -47,7 +47,9 @@ public NLogLoggerProvider(NLogProviderOptions options) /// New Logger public Microsoft.Extensions.Logging.ILogger CreateLogger(string name) { - var beginScopeExtractor = (Options?.CaptureMessageProperties ?? true) ? (_beginScopeParser ?? System.Threading.Interlocked.CompareExchange(ref _beginScopeParser, new NLogBeginScopeParser(Options), null)) : null; + var beginScopeExtractor = ((Options?.CaptureMessageProperties ?? true) && (Options?.IncludeScopes ?? true)) + ? (_beginScopeParser ?? System.Threading.Interlocked.CompareExchange(ref _beginScopeParser, new NLogBeginScopeParser(Options), null)) + : null; return new NLogLogger(LogManager.GetLogger(name), Options, beginScopeExtractor); } diff --git a/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs b/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs index 07fa80ec..d93a4181 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogProviderOptions.cs @@ -35,6 +35,11 @@ public class NLogProviderOptions /// public bool ParseMessageTemplates { get; set; } + /// + /// Enable capture of scope information and inject into and + /// + public bool IncludeScopes { get; set; } + /// Initializes a new instance of the class. public NLogProviderOptions() { @@ -43,6 +48,7 @@ public NLogProviderOptions() CaptureMessageTemplates = true; CaptureMessageProperties = true; ParseMessageTemplates = false; + IncludeScopes = true; } /// diff --git a/test/CustomBeginScopeTest.cs b/test/CustomBeginScopeTest.cs index 91534c33..7af32b34 100644 --- a/test/CustomBeginScopeTest.cs +++ b/test/CustomBeginScopeTest.cs @@ -1,6 +1,7 @@ using System; using System.Collections; using System.Collections.Generic; +using System.Threading.Tasks; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; using Xunit; @@ -10,16 +11,26 @@ namespace NLog.Extensions.Logging.Tests public class CustomBeginScopeTest : NLogTestBase { [Fact] - public void TestCallSiteSayHello() + public void TestNonSerializableSayHello() { var runner = GetRunner(); var target = new NLog.Targets.MemoryTarget() { Layout = "${message} ${ndlc}" }; NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(target); - runner.SayHello(); + runner.SayHello().Wait(); Assert.Single(target.Logs); Assert.Contains("Hello World", target.Logs[0]); } + [Fact] + public void TestNonSerializableSayNothing() + { + var runner = GetRunner(new NLogProviderOptions() { IncludeScopes = false }); + var target = new NLog.Targets.MemoryTarget() { Layout = "${message} ${ndlc}" }; + NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(target); + runner.SayHello().Wait(); + Assert.Single(target.Logs); + Assert.Contains("Hello ", target.Logs[0]); + } public class CustomBeginScopeTestRunner { @@ -30,10 +41,11 @@ public CustomBeginScopeTestRunner(ILogger logger) _logger = logger; } - public void SayHello() + public async Task SayHello() { using (_logger.BeginScope(new ActionLogScope("World"))) { + await Task.Yield(); _logger.LogInformation("Hello"); } } From d096a26fa6e15ec8bd9556ef9665a9c798932274 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Wed, 25 Jul 2018 23:46:14 +0200 Subject: [PATCH 05/13] Reduce enumerator-allocation when only using CaptureMessageProperties (Without CaptureMessageTemplates) --- .../Logging/NLogLogger.cs | 45 +++++++++++++++---- .../Logging/NLogLoggerProvider.cs | 4 +- test/CustomLoggerPropertyTest.cs | 19 ++++++-- 3 files changed, 54 insertions(+), 14 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs index f8c95850..86180237 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs @@ -32,19 +32,22 @@ public NLogLogger(Logger logger, NLogProviderOptions options, NLogBeginScopePars public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { var nLogLogLevel = ConvertLogLevel(logLevel); - if (!IsEnabled(nLogLogLevel)) + if (!_logger.IsEnabled(nLogLogLevel)) { return; } + if (formatter == null) { throw new ArgumentNullException(nameof(formatter)); } - var messageParameters = NLogMessageParameterList.TryParse(_options.CaptureMessageTemplates ? state as IReadOnlyList> : null); + var messageParameters = _options.CaptureMessageTemplates + ? NLogMessageParameterList.TryParse(state as IReadOnlyList>) + : null; LogEventInfo eventInfo = - TryParseLogEventInfo(nLogLogLevel, messageParameters) ?? + TryParseMessageTemplate(nLogLogLevel, messageParameters) ?? CreateLogEventInfo(nLogLogLevel, formatter(state, exception), messageParameters); if (exception != null) @@ -52,13 +55,16 @@ public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, EventId eventInfo.Exception = exception; } - CaptureEventId(eventInfo, eventId); - - if (messageParameters == null) + if (messageParameters == null && _options.CaptureMessageProperties) { - CaptureMessageProperties(eventInfo, state); + if (_options.CaptureMessageTemplates || !CaptureMessagePropertiesList(eventInfo, state)) + { + CaptureMessageProperties(eventInfo, state); + } } + CaptureEventId(eventInfo, eventId); + _logger.Log(typeof(Microsoft.Extensions.Logging.ILogger), eventInfo); } @@ -99,7 +105,7 @@ private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, string message, N /// /// Using the NLog MesageTemplate Parser will hurt performance: 1 x Microsoft Parser - 2 x NLog Parser - 1 x NLog Formatter /// - private LogEventInfo TryParseLogEventInfo(LogLevel nLogLogLevel, NLogMessageParameterList messageParameters) + private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, NLogMessageParameterList messageParameters) { if (messageParameters?.OriginalMessage != null && (messageParameters.HasComplexParameters || (_options.ParseMessageTemplates && messageParameters.Count > 0))) { @@ -304,7 +310,7 @@ private static Tuple CreateEventIdPropertyNames(string e private void CaptureMessageProperties(LogEventInfo eventInfo, TState state) { - if (_options.CaptureMessageProperties && state is IEnumerable> messageProperties) + if (state is IEnumerable> messageProperties) { foreach (var property in messageProperties) { @@ -316,6 +322,27 @@ private void CaptureMessageProperties(LogEventInfo eventInfo, TState sta } } + private bool CaptureMessagePropertiesList(LogEventInfo eventInfo, TState state) + { + if (state is IReadOnlyList> messageProperties) + { + for (int i = 0; i < messageProperties.Count; ++i) + { + var property = messageProperties[i]; + if (String.IsNullOrEmpty(property.Key)) + continue; + + if (i == messageProperties.Count - 1 && property.Key == OriginalFormatPropertyName) + continue; + + eventInfo.Properties[property.Key] = property.Value; + } + return true; + } + + return false; + } + /// /// Is logging enabled for this logger at this ? /// diff --git a/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs b/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs index ffe7bce8..f42efef7 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLoggerProvider.cs @@ -47,10 +47,10 @@ public NLogLoggerProvider(NLogProviderOptions options) /// New Logger public Microsoft.Extensions.Logging.ILogger CreateLogger(string name) { - var beginScopeExtractor = ((Options?.CaptureMessageProperties ?? true) && (Options?.IncludeScopes ?? true)) + var beginScopeParser = ((Options?.CaptureMessageProperties ?? true) && (Options?.IncludeScopes ?? true)) ? (_beginScopeParser ?? System.Threading.Interlocked.CompareExchange(ref _beginScopeParser, new NLogBeginScopeParser(Options), null)) : null; - return new NLogLogger(LogManager.GetLogger(name), Options, beginScopeExtractor); + return new NLogLogger(LogManager.GetLogger(name), Options, beginScopeParser); } /// diff --git a/test/CustomLoggerPropertyTest.cs b/test/CustomLoggerPropertyTest.cs index 6ca7fe64..b5abb10b 100644 --- a/test/CustomLoggerPropertyTest.cs +++ b/test/CustomLoggerPropertyTest.cs @@ -10,7 +10,7 @@ namespace NLog.Extensions.Logging.Tests public class CustomLoggerPropertyTest : NLogTestBase { [Fact] - public void TestExtraPropertySayHello() + public void TestExtraMessageTemplatePropertySayHello() { ConfigureServiceProvider((s) => s.AddSingleton(typeof(ILogger<>), typeof(SameAssemblyLogger<>))); var runner = GetRunner(); @@ -23,7 +23,7 @@ public void TestExtraPropertySayHello() } [Fact] - public void TestExtraPropertySayHigh5() + public void TestExtraMessageTemplatePropertySayHigh5() { ConfigureServiceProvider((s) => s.AddSingleton(typeof(ILogger<>), typeof(SameAssemblyLogger<>))); var runner = GetRunner(); @@ -35,6 +35,19 @@ public void TestExtraPropertySayHigh5() Assert.Equal(@"Hi 5|ActivityId=42", target.Logs[0]); } + [Fact] + public void TestExtraMessagePropertySayHi() + { + ConfigureServiceProvider((s) => s.AddSingleton(typeof(ILogger<>), typeof(SameAssemblyLogger<>)), new NLogProviderOptions() { CaptureMessageTemplates = false }); + var runner = GetRunner(); + + var target = new NLog.Targets.MemoryTarget() { Layout = "${message}|${all-event-properties}" }; + NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(target); + runner.SayHigh5(); + Assert.Single(target.Logs); + Assert.Equal(@"Hi 5|ActivityId=42, 0=5", target.Logs[0]); + } + public class SameAssemblyLogger : ILogger { private readonly Microsoft.Extensions.Logging.ILogger _logger; @@ -99,7 +112,7 @@ public MyLogEvent(TState state, Func formatter) public MyLogEvent AddProp(string name, T value) { - _properties.Add(new KeyValuePair(name, value)); + _properties.Insert(0, new KeyValuePair(name, value)); return this; } From 421160284c9fea8001c3d6f822aeb731ef490763 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Thu, 26 Jul 2018 08:47:49 +0200 Subject: [PATCH 06/13] Reduce allocation when logging message with no parameters --- .../Logging/NLogLogger.cs | 29 ++++++++++------- .../Logging/NLogMessageParameterList.cs | 31 +++++++++++++++++-- 2 files changed, 46 insertions(+), 14 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs index 86180237..5cef8809 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs @@ -42,13 +42,17 @@ public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, EventId throw new ArgumentNullException(nameof(formatter)); } - var messageParameters = _options.CaptureMessageTemplates - ? NLogMessageParameterList.TryParse(state as IReadOnlyList>) + var messageProperties = (_options.CaptureMessageTemplates || _options.CaptureMessageProperties) + ? state as IReadOnlyList> + : null; + + var messageParameters = (messageProperties != null && _options.CaptureMessageTemplates) + ? NLogMessageParameterList.TryParse(messageProperties) : null; LogEventInfo eventInfo = - TryParseMessageTemplate(nLogLogLevel, messageParameters) ?? - CreateLogEventInfo(nLogLogLevel, formatter(state, exception), messageParameters); + TryParseMessageTemplate(nLogLogLevel, messageProperties, messageParameters) ?? + CreateLogEventInfo(nLogLogLevel, formatter(state, exception), messageProperties, messageParameters); if (exception != null) { @@ -57,7 +61,7 @@ public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, EventId if (messageParameters == null && _options.CaptureMessageProperties) { - if (_options.CaptureMessageTemplates || !CaptureMessagePropertiesList(eventInfo, state)) + if (!CaptureMessagePropertiesList(eventInfo, messageProperties)) { CaptureMessageProperties(eventInfo, state); } @@ -69,12 +73,12 @@ public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, EventId } - private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, string message, NLogMessageParameterList messageParameters) + private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, string message, IReadOnlyList> messageProperties, NLogMessageParameterList messageParameters) { if (messageParameters?.HasComplexParameters == false) { // Parsing not needed, we take the fast route - var originalMessage = messageParameters.OriginalMessage as string; + var originalMessage = messageParameters.GetOriginalMessage(messageProperties); var eventInfo = new LogEventInfo(nLogLogLevel, _logger.Name, originalMessage ?? message, messageParameters.IsPositional ? _emptyParameterArray : messageParameters); if (originalMessage != null) { @@ -105,12 +109,13 @@ private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, string message, N /// /// Using the NLog MesageTemplate Parser will hurt performance: 1 x Microsoft Parser - 2 x NLog Parser - 1 x NLog Formatter /// - private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, NLogMessageParameterList messageParameters) + private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyList> messageProperties, NLogMessageParameterList messageParameters) { - if (messageParameters?.OriginalMessage != null && (messageParameters.HasComplexParameters || (_options.ParseMessageTemplates && messageParameters.Count > 0))) + if ((messageParameters?.HasOriginalMessage ?? false) && (messageParameters.HasComplexParameters || (_options.ParseMessageTemplates && messageParameters.Count > 0))) { // NLog MessageTemplate Parser must be used - var eventInfo = new LogEventInfo(nLogLogLevel, _logger.Name, null, messageParameters.OriginalMessage as string, _singleItemArray); + var originalMessage = messageParameters.GetOriginalMessage(messageProperties); + var eventInfo = new LogEventInfo(nLogLogLevel, _logger.Name, null, originalMessage, _singleItemArray); var messagetTemplateParameters = eventInfo.MessageTemplateParameters; // Forces parsing of OriginalMessage if (messagetTemplateParameters.Count > 0) { @@ -322,9 +327,9 @@ private void CaptureMessageProperties(LogEventInfo eventInfo, TState sta } } - private bool CaptureMessagePropertiesList(LogEventInfo eventInfo, TState state) + private bool CaptureMessagePropertiesList(LogEventInfo eventInfo, IReadOnlyList> messageProperties) { - if (state is IReadOnlyList> messageProperties) + if (messageProperties != null) { for (int i = 0; i < messageProperties.Count; ++i) { diff --git a/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs b/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs index 16cc01fe..d372aec6 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs @@ -11,8 +11,10 @@ namespace NLog.Extensions.Logging internal class NLogMessageParameterList : IList { private readonly IReadOnlyList> _parameterList; + private static readonly NLogMessageParameterList EmptyList = new NLogMessageParameterList(new KeyValuePair[0]); + private static readonly NLogMessageParameterList OriginalMessageList = new NLogMessageParameterList(new[] { new KeyValuePair(NLogLogger.OriginalFormatPropertyName, string.Empty) }); - public object OriginalMessage => _originalMessageIndex.HasValue ? _parameterList[_originalMessageIndex.Value].Value : null; + public bool HasOriginalMessage => _originalMessageIndex.HasValue; private readonly int? _originalMessageIndex; public bool HasComplexParameters => _hasMessageTemplateCapture || _isMixedPositional; @@ -42,7 +44,32 @@ public NLogMessageParameterList(IReadOnlyList> para /// public static NLogMessageParameterList TryParse(IReadOnlyList> parameterList) { - return parameterList?.Count > 0 ? new NLogMessageParameterList(parameterList) : null; + if (parameterList != null) + { + if (parameterList.Count > 1 || parameterList[0].Key != NLogLogger.OriginalFormatPropertyName) + { + return new NLogMessageParameterList(parameterList); + } + else if (parameterList.Count == 1) + { + return OriginalMessageList; // Skip allocation + } + else if (parameterList.Count == 0) + { + return EmptyList; // Skip allocation + } + } + + return null; + } + + public string GetOriginalMessage(IReadOnlyList> messageProperties) + { + if (_originalMessageIndex < messageProperties?.Count) + { + return messageProperties[_originalMessageIndex.Value].Value as string; + } + return null; } /// From 22234ea9a933966b60b327b6844c68fad11ecfce Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Fri, 27 Jul 2018 00:52:11 +0200 Subject: [PATCH 07/13] BeginScope can also be called with string-format (FormattedLogValues) --- .../Logging/NLogBeginScopeParser.cs | 5 ++- test/CustomBeginScopeTest.cs | 45 +++++++++++++------ 2 files changed, 36 insertions(+), 14 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs b/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs index 24ad9e62..f96c9ca4 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs @@ -54,7 +54,7 @@ public static IDisposable CreateDiagnosticLogicalContext(T state) if (state?.GetType().IsSerializable ?? true) return NestedDiagnosticsLogicalContext.Push(state); else - return NestedDiagnosticsLogicalContext.Push(state.ToString()); // Support ViewComponentLogScope, ActionLogScope and others + return NestedDiagnosticsLogicalContext.Push(state.ToString()); // Support HostingLogScope, ActionLogScope, FormattedLogValues and others #endif } catch (Exception ex) @@ -80,6 +80,9 @@ public static ScopeProperties CreateFromState(IReadOnlyList 0 && property.Key == NLogLogger.OriginalFormatPropertyName) + continue; // Handle BeginScope("Hello {World}", "Earth") + scope.AddProperty(property.Key, property.Value); } diff --git a/test/CustomBeginScopeTest.cs b/test/CustomBeginScopeTest.cs index 7af32b34..1abef9b6 100644 --- a/test/CustomBeginScopeTest.cs +++ b/test/CustomBeginScopeTest.cs @@ -2,7 +2,6 @@ using System.Collections; using System.Collections.Generic; using System.Threading.Tasks; -using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; using Xunit; @@ -14,22 +13,33 @@ public class CustomBeginScopeTest : NLogTestBase public void TestNonSerializableSayHello() { var runner = GetRunner(); - var target = new NLog.Targets.MemoryTarget() { Layout = "${message} ${ndlc}" }; + var target = new NLog.Targets.MemoryTarget() { Layout = "${message} ${mdlc:World}. Welcome ${ndlc}" }; NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(target); runner.SayHello().Wait(); Assert.Single(target.Logs); - Assert.Contains("Hello World", target.Logs[0]); + Assert.Equal("Hello Earth. Welcome Earth People", target.Logs[0]); } [Fact] public void TestNonSerializableSayNothing() { var runner = GetRunner(new NLogProviderOptions() { IncludeScopes = false }); - var target = new NLog.Targets.MemoryTarget() { Layout = "${message} ${ndlc}" }; + var target = new NLog.Targets.MemoryTarget() { Layout = "${message} ${mdlc:World}. Welcome ${ndlc}" }; NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(target); runner.SayHello().Wait(); Assert.Single(target.Logs); - Assert.Contains("Hello ", target.Logs[0]); + Assert.Equal("Hello . Welcome ", target.Logs[0]); + } + + [Fact] + public void TestNonSerializableSayHi() + { + var runner = GetRunner(); + var target = new NLog.Targets.MemoryTarget() { Layout = "${message} ${mdlc:World}. Welcome ${ndlc}" }; + NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(target); + runner.SayHi().Wait(); + Assert.Single(target.Logs); + Assert.Equal("Hi Earth. Welcome Earth People", target.Logs[0]); } public class CustomBeginScopeTestRunner @@ -43,26 +53,35 @@ public CustomBeginScopeTestRunner(ILogger logger) public async Task SayHello() { - using (_logger.BeginScope(new ActionLogScope("World"))) + using (_logger.BeginScope(new ActionLogScope("Earth"))) { await Task.Yield(); _logger.LogInformation("Hello"); } } + + public async Task SayHi() + { + using (_logger.BeginScope("{World} People", "Earth")) + { + await Task.Yield(); + _logger.LogInformation("Hi"); + } + } } private class ActionLogScope : IReadOnlyList> { - private readonly string _action; + private readonly string _world; - public ActionLogScope(string action) + public ActionLogScope(string world) { - if (action == null) + if (world == null) { - throw new ArgumentNullException(nameof(action)); + throw new ArgumentNullException(nameof(world)); } - _action = action; + _world = world; } public KeyValuePair this[int index] @@ -71,7 +90,7 @@ public KeyValuePair this[int index] { if (index == 0) { - return new KeyValuePair("ActionId", _action); + return new KeyValuePair("World", _world); } throw new IndexOutOfRangeException(nameof(index)); } @@ -91,7 +110,7 @@ public override string ToString() { // We don't include the _action.Id here because it's just an opaque guid, and if // you have text logging, you can already use the requestId for correlation. - return _action; + return string.Concat(_world, " People"); } IEnumerator IEnumerable.GetEnumerator() From a4f272976586b8391db563d621a1836e24f6ea4a Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Fri, 27 Jul 2018 20:53:55 +0200 Subject: [PATCH 08/13] BeginScope should return IDisposable where ToString returns ToString of input-state --- .../Logging/NLogBeginScopeParser.cs | 24 ++++++++++++++----- test/CustomBeginScopeTest.cs | 8 ++++--- 2 files changed, 23 insertions(+), 9 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs b/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs index f96c9ca4..e9063c93 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs @@ -66,16 +66,22 @@ public static IDisposable CreateDiagnosticLogicalContext(T state) private class ScopeProperties : IDisposable { - List _properties; + Stack _properties; /// /// Properties, never null and lazy init /// - List Properties => _properties ?? (_properties = new List()); + Stack Properties => _properties ?? (_properties = new Stack()); + + public ScopeProperties(int initialCapacity = 0) + { + if (initialCapacity > 0) + _properties = new Stack(initialCapacity); + } public static ScopeProperties CreateFromState(IReadOnlyList> messageProperties) { - ScopeProperties scope = new ScopeProperties(); + ScopeProperties scope = new ScopeProperties(messageProperties.Count + 1); for (int i = 0; i < messageProperties.Count; ++i) { @@ -185,7 +191,7 @@ private static void AddKeyValueProperty(ScopeProperties scope, KeyValuePair 0) { try { + property = properties.Pop(); property.Dispose(); } catch (Exception ex) @@ -212,6 +219,11 @@ public void Dispose() } } } + + public override string ToString() + { + return (_properties?.Count > 0 ? _properties.Peek()?.ToString() : null) ?? base.ToString(); + } } } } diff --git a/test/CustomBeginScopeTest.cs b/test/CustomBeginScopeTest.cs index 1abef9b6..cfc342aa 100644 --- a/test/CustomBeginScopeTest.cs +++ b/test/CustomBeginScopeTest.cs @@ -37,9 +37,10 @@ public void TestNonSerializableSayHi() var runner = GetRunner(); var target = new NLog.Targets.MemoryTarget() { Layout = "${message} ${mdlc:World}. Welcome ${ndlc}" }; NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(target); - runner.SayHi().Wait(); + var scopeString = runner.SayHi().Result; Assert.Single(target.Logs); Assert.Equal("Hi Earth. Welcome Earth People", target.Logs[0]); + Assert.Equal("Earth People", scopeString); } public class CustomBeginScopeTestRunner @@ -60,12 +61,13 @@ public async Task SayHello() } } - public async Task SayHi() + public async Task SayHi() { - using (_logger.BeginScope("{World} People", "Earth")) + using (var scopeState = _logger.BeginScope("{World} People", "Earth")) { await Task.Yield(); _logger.LogInformation("Hi"); + return scopeState.ToString(); } } } From 2bbddba39d52165e43f1b3e79040b444ed1c2f86 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Thu, 2 Aug 2018 00:22:33 +0200 Subject: [PATCH 09/13] NLogBeginScopeParser - Reduce complexity of the individual methods --- .../Logging/NLogBeginScopeParser.cs | 123 +++++++++--------- 1 file changed, 60 insertions(+), 63 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs b/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs index e9063c93..3ea5e7aa 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs @@ -23,16 +23,17 @@ public IDisposable ParseBeginScope(T state) { if (_options.CaptureMessageProperties) { - if (state is IReadOnlyList> contextProperties) + if (state is IReadOnlyList> scopePropertyList) { - return ScopeProperties.CreateFromState(contextProperties); + return ScopeProperties.CaptureScopeProperties(scopePropertyList); } if (!(state is string)) { - var scope = ScopeProperties.CreateFromStateExtractor(state, _scopeStateExtractors); - if (scope != null) - return scope; + if (state is System.Collections.IEnumerable scopePropertyCollection) + return ScopeProperties.CaptureScopeProperties(scopePropertyCollection, _scopeStateExtractors); + else + return ScopeProperties.CaptureScopeProperty(state, _scopeStateExtractors); } else { @@ -79,27 +80,73 @@ public ScopeProperties(int initialCapacity = 0) _properties = new Stack(initialCapacity); } - public static ScopeProperties CreateFromState(IReadOnlyList> messageProperties) + public static ScopeProperties CaptureScopeProperties(IReadOnlyList> scopePropertyList) { - ScopeProperties scope = new ScopeProperties(messageProperties.Count + 1); + ScopeProperties scope = new ScopeProperties(scopePropertyList.Count + 1); - for (int i = 0; i < messageProperties.Count; ++i) + for (int i = 0; i < scopePropertyList.Count; ++i) { - var property = messageProperties[i]; - if (i == messageProperties.Count - 1 && i > 0 && property.Key == NLogLogger.OriginalFormatPropertyName) + var property = scopePropertyList[i]; + if (i == scopePropertyList.Count - 1 && i > 0 && property.Key == NLogLogger.OriginalFormatPropertyName) continue; // Handle BeginScope("Hello {World}", "Earth") scope.AddProperty(property.Key, property.Value); } - scope.AddDispose(CreateDiagnosticLogicalContext(messageProperties)); + scope.AddDispose(CreateDiagnosticLogicalContext(scopePropertyList)); return scope; } - public static bool TryCreateExtractor(ConcurrentDictionary, Func>> stateExractor, T property, out KeyValuePair, Func> keyValueExtractor) + public static ScopeProperties CaptureScopeProperties(System.Collections.IEnumerable scopePropertyCollection, ConcurrentDictionary, Func>> stateExractor) { - Type propertyType = property.GetType(); + ScopeProperties scope = null; + var keyValueExtractor = default(KeyValuePair, Func>); + foreach (var property in scopePropertyCollection) + { + if (property == null) + return null; + + if (scope == null) + { + if (!TryCreateExtractor(stateExractor, property.GetType(), out keyValueExtractor)) + return null; + + scope = new ScopeProperties(); + } + + AddKeyValueProperty(scope, keyValueExtractor, property); + } + scope.AddDispose(CreateDiagnosticLogicalContext(scopePropertyCollection)); + return scope; + } + + public static ScopeProperties CaptureScopeProperty(TState scopeProperty, ConcurrentDictionary, Func>> stateExractor) + { + if (!TryCreateExtractor(stateExractor, scopeProperty.GetType(), out var keyValueExtractor)) + return null; + + var scope = new ScopeProperties(); + AddKeyValueProperty(scope, keyValueExtractor, scopeProperty); + scope.AddDispose(CreateDiagnosticLogicalContext(scopeProperty)); + return scope; + } + private static void AddKeyValueProperty(ScopeProperties scope, KeyValuePair, Func> keyValueExtractor, object property) + { + try + { + var propertyKey = keyValueExtractor.Key.Invoke(property); + var propertyValue = keyValueExtractor.Value.Invoke(property); + scope.AddProperty(propertyKey?.ToString() ?? string.Empty, propertyValue); + } + catch (Exception ex) + { + InternalLogger.Debug(ex, "Exception in BeginScope add property"); + } + } + + public static bool TryCreateExtractor(ConcurrentDictionary, Func>> stateExractor, Type propertyType, out KeyValuePair, Func> keyValueExtractor) + { if (!stateExractor.TryGetValue(propertyType, out keyValueExtractor)) { try @@ -138,56 +185,6 @@ public static bool TryCreateExtractor(ConcurrentDictionary(TState state, ConcurrentDictionary, Func>> stateExractor) - { - ScopeProperties scope = null; - var keyValueExtractor = default(KeyValuePair, Func>); - if (state is System.Collections.IEnumerable messageProperties) - { - foreach (var property in messageProperties) - { - if (property == null) - return null; - - if (scope == null) - { - if (!TryCreateExtractor(stateExractor, property, out keyValueExtractor)) - return null; - - scope = new ScopeProperties(); - } - - AddKeyValueProperty(scope, keyValueExtractor, property); - } - } - else - { - if (!TryCreateExtractor(stateExractor, state, out keyValueExtractor)) - return null; - - scope = new ScopeProperties(); - AddKeyValueProperty(scope, keyValueExtractor, state); - } - - if (scope != null) - scope.AddDispose(CreateDiagnosticLogicalContext(state)); - return scope; - } - - private static void AddKeyValueProperty(ScopeProperties scope, KeyValuePair, Func> keyValueExtractor, object property) - { - try - { - var propertyKey = keyValueExtractor.Key.Invoke(property); - var propertyValue = keyValueExtractor.Value.Invoke(property); - scope.AddProperty(propertyKey?.ToString() ?? string.Empty, propertyValue); - } - catch (Exception ex) - { - InternalLogger.Debug(ex, "Exception in BeginScope add property"); - } - } - public void AddDispose(IDisposable disposable) { if (disposable != null) From 728870a37fa00be4c1fb572376266bbb3458dfa4 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Thu, 2 Aug 2018 00:30:16 +0200 Subject: [PATCH 10/13] NLogBeginScopeParser - Reduce complexity of the individual methods --- .../Logging/NLogBeginScopeParser.cs | 54 +++++++++++-------- 1 file changed, 31 insertions(+), 23 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs b/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs index 3ea5e7aa..9b0e0bdd 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogBeginScopeParser.cs @@ -108,7 +108,7 @@ public static ScopeProperties CaptureScopeProperties(System.Collections.IEnumera if (scope == null) { - if (!TryCreateExtractor(stateExractor, property.GetType(), out keyValueExtractor)) + if (!TryLookupExtractor(stateExractor, property.GetType(), out keyValueExtractor)) return null; scope = new ScopeProperties(); @@ -122,7 +122,7 @@ public static ScopeProperties CaptureScopeProperties(System.Collections.IEnumera public static ScopeProperties CaptureScopeProperty(TState scopeProperty, ConcurrentDictionary, Func>> stateExractor) { - if (!TryCreateExtractor(stateExractor, scopeProperty.GetType(), out var keyValueExtractor)) + if (!TryLookupExtractor(stateExractor, scopeProperty.GetType(), out var keyValueExtractor)) return null; var scope = new ScopeProperties(); @@ -145,32 +145,13 @@ private static void AddKeyValueProperty(ScopeProperties scope, KeyValuePair, Func>> stateExractor, Type propertyType, out KeyValuePair, Func> keyValueExtractor) + private static bool TryLookupExtractor(ConcurrentDictionary, Func>> stateExractor, Type propertyType, out KeyValuePair, Func> keyValueExtractor) { if (!stateExractor.TryGetValue(propertyType, out keyValueExtractor)) { try { - var itemType = propertyType.GetTypeInfo(); - if (!itemType.IsGenericType || itemType.GetGenericTypeDefinition() != typeof(KeyValuePair<,>)) - return false; - - var keyPropertyInfo = itemType.GetDeclaredProperty("Key"); - var valuePropertyInfo = itemType.GetDeclaredProperty("Value"); - if (valuePropertyInfo == null || keyPropertyInfo == null) - return false; - - var keyValuePairObjParam = System.Linq.Expressions.Expression.Parameter(typeof(object), "pair"); - var keyValuePairTypeParam = System.Linq.Expressions.Expression.Convert(keyValuePairObjParam, propertyType); - - var propertyKeyAccess = System.Linq.Expressions.Expression.Property(keyValuePairTypeParam, keyPropertyInfo); - var propertyKeyAccessObj = System.Linq.Expressions.Expression.Convert(propertyKeyAccess, typeof(object)); - var propertyKeyLambda = System.Linq.Expressions.Expression.Lambda>(propertyKeyAccessObj, keyValuePairObjParam).Compile(); - - var propertyValueAccess = System.Linq.Expressions.Expression.Property(keyValuePairTypeParam, valuePropertyInfo); - var propertyValueLambda = System.Linq.Expressions.Expression.Lambda>(propertyValueAccess, keyValuePairObjParam).Compile(); - - keyValueExtractor = new KeyValuePair, Func>(propertyKeyLambda, propertyValueLambda); + return TryBuildExtractor(propertyType, out keyValueExtractor); } catch (Exception ex) { @@ -185,6 +166,33 @@ public static bool TryCreateExtractor(ConcurrentDictionary, Func> keyValueExtractor) + { + keyValueExtractor = default(KeyValuePair, Func>); + + var itemType = propertyType.GetTypeInfo(); + if (!itemType.IsGenericType || itemType.GetGenericTypeDefinition() != typeof(KeyValuePair<,>)) + return false; + + var keyPropertyInfo = itemType.GetDeclaredProperty("Key"); + var valuePropertyInfo = itemType.GetDeclaredProperty("Value"); + if (valuePropertyInfo == null || keyPropertyInfo == null) + return false; + + var keyValuePairObjParam = System.Linq.Expressions.Expression.Parameter(typeof(object), "pair"); + var keyValuePairTypeParam = System.Linq.Expressions.Expression.Convert(keyValuePairObjParam, propertyType); + + var propertyKeyAccess = System.Linq.Expressions.Expression.Property(keyValuePairTypeParam, keyPropertyInfo); + var propertyKeyAccessObj = System.Linq.Expressions.Expression.Convert(propertyKeyAccess, typeof(object)); + var propertyKeyLambda = System.Linq.Expressions.Expression.Lambda>(propertyKeyAccessObj, keyValuePairObjParam).Compile(); + + var propertyValueAccess = System.Linq.Expressions.Expression.Property(keyValuePairTypeParam, valuePropertyInfo); + var propertyValueLambda = System.Linq.Expressions.Expression.Lambda>(propertyValueAccess, keyValuePairObjParam).Compile(); + + keyValueExtractor = new KeyValuePair, Func>(propertyKeyLambda, propertyValueLambda); + return true; + } + public void AddDispose(IDisposable disposable) { if (disposable != null) From 25b231defc21a69e102f77d78c8cd0f2341c07f9 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Thu, 2 Aug 2018 00:44:39 +0200 Subject: [PATCH 11/13] NLogLogger - Move some complexity out of Log-method --- .../Logging/NLogLogger.cs | 93 +++++++++++-------- 1 file changed, 52 insertions(+), 41 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs index 5cef8809..f9dd666f 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs @@ -42,6 +42,15 @@ public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, EventId throw new ArgumentNullException(nameof(formatter)); } + LogEventInfo eventInfo = CreateLogEventInfo(nLogLogLevel, state, exception, formatter); + + CaptureEventId(eventInfo, eventId); + + _logger.Log(typeof(Microsoft.Extensions.Logging.ILogger), eventInfo); + } + + private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, TState state, Exception exception, Func formatter) + { var messageProperties = (_options.CaptureMessageTemplates || _options.CaptureMessageProperties) ? state as IReadOnlyList> : null; @@ -50,56 +59,23 @@ public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, EventId ? NLogMessageParameterList.TryParse(messageProperties) : null; + string formattedMesage = null; LogEventInfo eventInfo = TryParseMessageTemplate(nLogLogLevel, messageProperties, messageParameters) ?? - CreateLogEventInfo(nLogLogLevel, formatter(state, exception), messageProperties, messageParameters); + TryCaptureMessageTemplate(nLogLogLevel, formattedMesage ?? (formattedMesage = formatter(state, exception)), messageProperties, messageParameters) ?? + CreateSimpleLogEventInfo(nLogLogLevel, formattedMesage, messageProperties, messageParameters); - if (exception != null) + if (messageParameters == null && messageProperties == null && _options.CaptureMessageProperties) { - eventInfo.Exception = exception; + CaptureMessageProperties(eventInfo, state); } - if (messageParameters == null && _options.CaptureMessageProperties) + if (exception != null) { - if (!CaptureMessagePropertiesList(eventInfo, messageProperties)) - { - CaptureMessageProperties(eventInfo, state); - } + eventInfo.Exception = exception; } - CaptureEventId(eventInfo, eventId); - - _logger.Log(typeof(Microsoft.Extensions.Logging.ILogger), eventInfo); - } - - - private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, string message, IReadOnlyList> messageProperties, NLogMessageParameterList messageParameters) - { - if (messageParameters?.HasComplexParameters == false) - { - // Parsing not needed, we take the fast route - var originalMessage = messageParameters.GetOriginalMessage(messageProperties); - var eventInfo = new LogEventInfo(nLogLogLevel, _logger.Name, originalMessage ?? message, messageParameters.IsPositional ? _emptyParameterArray : messageParameters); - if (originalMessage != null) - { - SetLogEventMessageFormatter(eventInfo, messageParameters, message); - } - return eventInfo; - } - else - { - // Parsing failed or no messageParameters - var eventInfo = LogEventInfo.Create(nLogLogLevel, _logger.Name, message); - if (messageParameters?.Count > 0) - { - for (int i = 0; i < messageParameters.Count; ++i) - { - var property = messageParameters[i]; - eventInfo.Properties[property.Name] = property.Value; - } - } - return eventInfo; - } + return eventInfo; } /// @@ -136,6 +112,41 @@ private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyLis return null; // Parsing not needed } + private LogEventInfo TryCaptureMessageTemplate(LogLevel nLogLogLevel, string message, IReadOnlyList> messageProperties, NLogMessageParameterList messageParameters) + { + if (messageParameters?.HasComplexParameters == false) + { + // Parsing not needed, we take the fast route + var originalMessage = messageParameters.GetOriginalMessage(messageProperties); + var eventInfo = new LogEventInfo(nLogLogLevel, _logger.Name, originalMessage ?? message, messageParameters.IsPositional ? _emptyParameterArray : messageParameters); + if (originalMessage != null) + { + SetLogEventMessageFormatter(eventInfo, messageParameters, message); + } + return eventInfo; + } + return null; + } + + private LogEventInfo CreateSimpleLogEventInfo(LogLevel nLogLogLevel, string message, IReadOnlyList> messageProperties, NLogMessageParameterList messageParameters) + { + // Parsing failed or no messageParameters + var eventInfo = LogEventInfo.Create(nLogLogLevel, _logger.Name, message); + if (messageParameters != null) + { + for (int i = 0; i < messageParameters.Count; ++i) + { + var property = messageParameters[i]; + eventInfo.Properties[property.Name] = property.Value; + } + } + else if (messageProperties != null && _options.CaptureMessageProperties) + { + CaptureMessagePropertiesList(eventInfo, messageProperties); + } + return eventInfo; + } + /// /// Allocates object[]-array for after checking /// for mismatch between Microsoft Extension Logging and NLog Message Template Parser From bfea3280298213aba1fed6a3115ce6a3e33d5ac8 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Thu, 2 Aug 2018 23:44:23 +0200 Subject: [PATCH 12/13] NLogLogger - Move some complexity out of Log-method --- .../Logging/NLogLogger.cs | 60 +++++++++---------- 1 file changed, 29 insertions(+), 31 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs index f9dd666f..97e60ee2 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs @@ -46,6 +46,11 @@ public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, EventId CaptureEventId(eventInfo, eventId); + if (exception != null) + { + eventInfo.Exception = exception; + } + _logger.Log(typeof(Microsoft.Extensions.Logging.ILogger), eventInfo); } @@ -55,29 +60,24 @@ private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, TState st ? state as IReadOnlyList> : null; - var messageParameters = (messageProperties != null && _options.CaptureMessageTemplates) - ? NLogMessageParameterList.TryParse(messageProperties) - : null; - - string formattedMesage = null; LogEventInfo eventInfo = - TryParseMessageTemplate(nLogLogLevel, messageProperties, messageParameters) ?? - TryCaptureMessageTemplate(nLogLogLevel, formattedMesage ?? (formattedMesage = formatter(state, exception)), messageProperties, messageParameters) ?? - CreateSimpleLogEventInfo(nLogLogLevel, formattedMesage, messageProperties, messageParameters); + TryParseMessageTemplate(nLogLogLevel, messageProperties, out var messageParameters) ?? + CreateLogEventInfo(nLogLogLevel, formatter(state, exception), messageProperties, messageParameters); if (messageParameters == null && messageProperties == null && _options.CaptureMessageProperties) { - CaptureMessageProperties(eventInfo, state); - } - - if (exception != null) - { - eventInfo.Exception = exception; + CaptureMessageProperties(eventInfo, state as IEnumerable>); } return eventInfo; } + private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, string formattedMessage, IReadOnlyList> messageProperties, NLogMessageParameterList messageParameters) + { + return TryCaptureMessageTemplate(nLogLogLevel, formattedMessage, messageProperties, messageParameters) ?? + CreateSimpleLogEventInfo(nLogLogLevel, formattedMessage, messageProperties, messageParameters); + } + /// /// Checks if the already parsed input message-parameters must be sent through /// the NLog MessageTemplate Parser for proper handling of message-template syntax. @@ -85,8 +85,12 @@ private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, TState st /// /// Using the NLog MesageTemplate Parser will hurt performance: 1 x Microsoft Parser - 2 x NLog Parser - 1 x NLog Formatter /// - private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyList> messageProperties, NLogMessageParameterList messageParameters) + private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyList> messageProperties, out NLogMessageParameterList messageParameters) { + messageParameters = (messageProperties != null && _options.CaptureMessageTemplates) + ? NLogMessageParameterList.TryParse(messageProperties) + : null; + if ((messageParameters?.HasOriginalMessage ?? false) && (messageParameters.HasComplexParameters || (_options.ParseMessageTemplates && messageParameters.Count > 0))) { // NLog MessageTemplate Parser must be used @@ -324,9 +328,9 @@ private static Tuple CreateEventIdPropertyNames(string e return eventIdPropertyNames; } - private void CaptureMessageProperties(LogEventInfo eventInfo, TState state) + private void CaptureMessageProperties(LogEventInfo eventInfo, IEnumerable> messageProperties) { - if (state is IEnumerable> messageProperties) + if (messageProperties != null) { foreach (var property in messageProperties) { @@ -338,25 +342,19 @@ private void CaptureMessageProperties(LogEventInfo eventInfo, TState sta } } - private bool CaptureMessagePropertiesList(LogEventInfo eventInfo, IReadOnlyList> messageProperties) + private void CaptureMessagePropertiesList(LogEventInfo eventInfo, IReadOnlyList> messageProperties) { - if (messageProperties != null) + for (int i = 0; i < messageProperties.Count; ++i) { - for (int i = 0; i < messageProperties.Count; ++i) - { - var property = messageProperties[i]; - if (String.IsNullOrEmpty(property.Key)) - continue; + var property = messageProperties[i]; + if (String.IsNullOrEmpty(property.Key)) + continue; - if (i == messageProperties.Count - 1 && property.Key == OriginalFormatPropertyName) - continue; + if (i == messageProperties.Count - 1 && property.Key == OriginalFormatPropertyName) + continue; - eventInfo.Properties[property.Key] = property.Value; - } - return true; + eventInfo.Properties[property.Key] = property.Value; } - - return false; } /// From c2c50c998018e0d323d9e03f8ea9ade2bbe7c349 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Fri, 3 Aug 2018 02:29:57 +0200 Subject: [PATCH 13/13] NLogLogger - Move some complexity out of Log-method --- .../Logging/NLogLogger.cs | 61 +++++++++++++------ .../Logging/NLogMessageParameterList.cs | 28 ++++----- 2 files changed, 57 insertions(+), 32 deletions(-) diff --git a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs index 97e60ee2..955cc55c 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogLogger.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogLogger.cs @@ -1,9 +1,6 @@ using System; -using System.Collections.Concurrent; using System.Collections.Generic; -using System.Reflection; using Microsoft.Extensions.Logging; -using NLog.Common; using NLog.MessageTemplates; namespace NLog.Extensions.Logging @@ -87,13 +84,10 @@ private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, string formattedM /// private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyList> messageProperties, out NLogMessageParameterList messageParameters) { - messageParameters = (messageProperties != null && _options.CaptureMessageTemplates) - ? NLogMessageParameterList.TryParse(messageProperties) - : null; + messageParameters = TryParseMessageParameterList(messageProperties); - if ((messageParameters?.HasOriginalMessage ?? false) && (messageParameters.HasComplexParameters || (_options.ParseMessageTemplates && messageParameters.Count > 0))) + if (messageParameters?.HasMessageTemplateSyntax(_options.ParseMessageTemplates)==true) { - // NLog MessageTemplate Parser must be used var originalMessage = messageParameters.GetOriginalMessage(messageProperties); var eventInfo = new LogEventInfo(nLogLogLevel, _logger.Name, null, originalMessage, _singleItemArray); var messagetTemplateParameters = eventInfo.MessageTemplateParameters; // Forces parsing of OriginalMessage @@ -101,12 +95,7 @@ private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyLis { // We have parsed the message and found parameters, now we need to do the parameter mapping eventInfo.Parameters = CreateLogEventInfoParameters(messageParameters, messagetTemplateParameters, out var extraProperties); - if (extraProperties?.Count > 0) - { - // Need to harvest additional parameters - foreach (var property in extraProperties) - eventInfo.Properties[property.Name] = property.Value; - } + AddExtraPropertiesToLogEvent(eventInfo, extraProperties); return eventInfo; } @@ -116,6 +105,31 @@ private LogEventInfo TryParseMessageTemplate(LogLevel nLogLogLevel, IReadOnlyLis return null; // Parsing not needed } + /// + /// Convert IReadOnlyList to + /// + /// + /// + private NLogMessageParameterList TryParseMessageParameterList(IReadOnlyList> messageProperties) + { + return (messageProperties != null && _options.CaptureMessageTemplates) + ? NLogMessageParameterList.TryParse(messageProperties) + : null; + } + + /// + /// Append extra property on + /// + private static void AddExtraPropertiesToLogEvent(LogEventInfo eventInfo, List extraProperties) + { + if (extraProperties?.Count > 0) + { + // Need to harvest additional parameters + foreach (var property in extraProperties) + eventInfo.Properties[property.Name] = property.Value; + } + } + private LogEventInfo TryCaptureMessageTemplate(LogLevel nLogLogLevel, string message, IReadOnlyList> messageProperties, NLogMessageParameterList messageParameters) { if (messageParameters?.HasComplexParameters == false) @@ -233,8 +247,7 @@ private static object[] CreateStructuredLogEventInfoParameters(NLogMessageParame if (extraProperty) { - extraProperties = extraProperties ?? new List(); - extraProperties.Add(messageParameters[i]); + extraProperties = AddExtraProperty(extraProperties, messageParameters[i]); } } @@ -262,14 +275,26 @@ private static object[] CreatePositionalLogEventInfoParameters(NLogMessageParame } else { - extraProperties = extraProperties ?? new List(); - extraProperties.Add(messageParameters[i]); + extraProperties = AddExtraProperty(extraProperties, messageParameters[i]); } } return paramsArray ?? new object[maxIndex + 1]; } + /// + /// Add Property and init list if needed + /// + /// + /// + /// list with at least one item + private static List AddExtraProperty(List extraProperties, MessageTemplateParameter item) + { + extraProperties = extraProperties ?? new List(); + extraProperties.Add(item); + return extraProperties; + } + /// /// Find max index of the parameters /// diff --git a/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs b/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs index d372aec6..8c4af3aa 100644 --- a/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs +++ b/src/NLog.Extensions.Logging/Logging/NLogMessageParameterList.cs @@ -44,23 +44,23 @@ public NLogMessageParameterList(IReadOnlyList> para /// public static NLogMessageParameterList TryParse(IReadOnlyList> parameterList) { - if (parameterList != null) + if (parameterList.Count > 1 || parameterList[0].Key != NLogLogger.OriginalFormatPropertyName) { - if (parameterList.Count > 1 || parameterList[0].Key != NLogLogger.OriginalFormatPropertyName) - { - return new NLogMessageParameterList(parameterList); - } - else if (parameterList.Count == 1) - { - return OriginalMessageList; // Skip allocation - } - else if (parameterList.Count == 0) - { - return EmptyList; // Skip allocation - } + return new NLogMessageParameterList(parameterList); + } + else if (parameterList.Count == 1) + { + return OriginalMessageList; // Skip allocation + } + else + { + return EmptyList; // Skip allocation } + } - return null; + public bool HasMessageTemplateSyntax(bool parseMessageTemplates) + { + return HasOriginalMessage && (HasComplexParameters || (parseMessageTemplates && Count > 0)); } public string GetOriginalMessage(IReadOnlyList> messageProperties)