From cf94721c74786d4571c144a5e1275af923404821 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Sun, 15 Oct 2017 11:11:02 +0200 Subject: [PATCH] MessageProperties - Allow capture of message properties through ILogger-state and ILogger-scope --- src/NLog.Extensions.Logging/NLogLogger.cs | 125 +++++++++++++++--- .../NLogProviderOptions.cs | 5 + test/LoggerTests.cs | 27 +++- 3 files changed, 138 insertions(+), 19 deletions(-) diff --git a/src/NLog.Extensions.Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/NLogLogger.cs index 48c42e2d..4aebbaa3 100644 --- a/src/NLog.Extensions.Logging/NLogLogger.cs +++ b/src/NLog.Extensions.Logging/NLogLogger.cs @@ -40,25 +40,12 @@ public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, EventId var messageTemplate = _options.CaptureMessageTemplates ? state as IReadOnlyList> : null; LogEventInfo eventInfo = CreateLogEventInfo(nLogLogLevel, message, messageTemplate); eventInfo.Exception = exception; - if (!_options.IgnoreEmptyEventId || eventId.Id != 0 || !string.IsNullOrEmpty(eventId.Name)) - { - // Attempt to reuse the same string-allocations based on the current - var eventIdPropertyNames = _eventIdPropertyNames ?? new Tuple(null, null, null); - var eventIdSeparator = _options.EventIdSeparator ?? string.Empty; - if (!ReferenceEquals(eventIdPropertyNames.Item1, eventIdSeparator)) - { - // Perform atomic cache update of the string-allocations matching the current separator - eventIdPropertyNames = new Tuple( - eventIdSeparator, - string.Concat("EventId", eventIdSeparator, "Id"), - string.Concat("EventId", eventIdSeparator, "Name")); - _eventIdPropertyNames = eventIdPropertyNames; - } - var idIsZero = eventId.Id == 0; - eventInfo.Properties[eventIdPropertyNames.Item2] = idIsZero ? ZeroEventId : eventId.Id; - eventInfo.Properties[eventIdPropertyNames.Item3] = eventId.Name; - eventInfo.Properties["EventId"] = idIsZero && eventId.Name == null ? EmptyEventId : eventId; + CaptureEventId(eventId, eventInfo); + + if (_options.CaptureMessageProperties && messageTemplate == null) + { + CaptureMessageProperties(state, eventInfo); } _logger.Log(eventInfo); @@ -118,6 +105,44 @@ private LogEventInfo CreateLogEventInfo(LogLevel nLogLogLevel, string message, I return LogEventInfo.Create(nLogLogLevel, _logger.Name, message); } + private void CaptureEventId(EventId eventId, LogEventInfo eventInfo) + { + if (!_options.IgnoreEmptyEventId || eventId.Id != 0 || !string.IsNullOrEmpty(eventId.Name)) + { + // Attempt to reuse the same string-allocations based on the current + var eventIdPropertyNames = _eventIdPropertyNames ?? new Tuple(null, null, null); + var eventIdSeparator = _options.EventIdSeparator ?? string.Empty; + if (!ReferenceEquals(eventIdPropertyNames.Item1, eventIdSeparator)) + { + // Perform atomic cache update of the string-allocations matching the current separator + eventIdPropertyNames = new Tuple( + eventIdSeparator, + string.Concat("EventId", eventIdSeparator, "Id"), + string.Concat("EventId", eventIdSeparator, "Name")); + _eventIdPropertyNames = eventIdPropertyNames; + } + + var idIsZero = eventId.Id == 0; + eventInfo.Properties[eventIdPropertyNames.Item2] = idIsZero ? ZeroEventId : eventId.Id; + eventInfo.Properties[eventIdPropertyNames.Item3] = eventId.Name; + eventInfo.Properties["EventId"] = idIsZero && eventId.Name == null ? EmptyEventId : eventId; + } + } + + private static void CaptureMessageProperties(TState state, LogEventInfo eventInfo) + { + if (state is IEnumerable> messageProperties) + { + foreach (var property in messageProperties) + { + if (string.IsNullOrEmpty(property.Key)) + continue; + + eventInfo.Properties[property.Key] = property.Value; + } + } + } + /// /// Is logging enabled for this logger at this ? /// @@ -165,6 +190,51 @@ private static LogLevel ConvertLogLevel(Microsoft.Extensions.Logging.LogLevel lo } } + class ScopeProperties : IDisposable + { + List _properties; + List Properties { get { return _properties ?? (_properties = new List()); } } + + class ScopeProperty : IDisposable + { + string _key; + + public ScopeProperty(string key, object value) + { + _key = key; + MappedDiagnosticsLogicalContext.Set(key, value); + } + + public void Dispose() + { + MappedDiagnosticsLogicalContext.Remove(_key); + } + } + + public void AddDispose(IDisposable disposable) + { + 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) + { + property.Dispose(); + } + } + } + } + /// /// Begin a scope. Use in config with ${ndlc} /// @@ -177,6 +247,25 @@ public IDisposable BeginScope(TState state) throw new ArgumentNullException(nameof(state)); } + if (_options.CaptureMessageProperties) + { + if (state is IEnumerable> messageProperties) + { + ScopeProperties scope = new ScopeProperties(); + + foreach (var property in messageProperties) + { + if (string.IsNullOrEmpty(property.Key)) + continue; + + scope.AddProperty(property.Key, property.Value); + } + + scope.AddDispose(NestedDiagnosticsLogicalContext.Push(state)); + return scope; + } + } + return NestedDiagnosticsLogicalContext.Push(state); } } diff --git a/src/NLog.Extensions.Logging/NLogProviderOptions.cs b/src/NLog.Extensions.Logging/NLogProviderOptions.cs index 1ca7eb1d..5f36998b 100644 --- a/src/NLog.Extensions.Logging/NLogProviderOptions.cs +++ b/src/NLog.Extensions.Logging/NLogProviderOptions.cs @@ -27,6 +27,11 @@ public class NLogProviderOptions /// public bool CaptureMessageTemplates { get; set; } + /// + /// Enable conversion of + /// + public bool CaptureMessageProperties { get; set; } + /// Initializes a new instance of the class. public NLogProviderOptions() { diff --git a/test/LoggerTests.cs b/test/LoggerTests.cs index 26590b29..648a9ab6 100644 --- a/test/LoggerTests.cs +++ b/test/LoggerTests.cs @@ -1,4 +1,5 @@ using System; +using System.Collections.Generic; using System.Linq; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; @@ -53,6 +54,17 @@ public void TestStructuredLogging() Assert.Equal("NLog.Extensions.Logging.Tests.LoggerTests.Runner|DEBUG|message with id and 1 parameters |01", target.Logs.FirstOrDefault()); } + [Fact] + public void TestMessageProperties() + { + GetRunner().LogDebugWithMessageProperties(); + + var target = GetTarget(); + Assert.Equal("NLog.Extensions.Logging.Tests.LoggerTests.Runner|DEBUG|message with id and 1 property |01", target.Logs.FirstOrDefault()); + + GetRunner().LogWithScopeParameters(); + } + [Theory] [InlineData(Microsoft.Extensions.Logging.LogLevel.Critical, "NLog.Extensions.Logging.Tests.LoggerTests.Runner|FATAL|message Exception of type 'System.Exception' was thrown.|20")] [InlineData(Microsoft.Extensions.Logging.LogLevel.Debug, "NLog.Extensions.Logging.Tests.LoggerTests.Runner|DEBUG|message Exception of type 'System.Exception' was thrown.|20")] @@ -168,7 +180,7 @@ private static IServiceProvider BuildDi() var serviceProvider = services.BuildServiceProvider(); var loggerFactory = serviceProvider.GetRequiredService(); - loggerFactory.AddNLog(new NLogProviderOptions() { CaptureMessageTemplates = true }); + loggerFactory.AddNLog(new NLogProviderOptions() { CaptureMessageTemplates = true, CaptureMessageProperties = true }); loggerFactory.ConfigureNLog("nlog.config"); return serviceProvider; } @@ -224,6 +236,11 @@ public void LogDebugWithStructuredParameters() _logger.LogDebug("message with id and {ParameterCount} parameters", "1"); } + public void LogDebugWithMessageProperties() + { + _logger.Log(Microsoft.Extensions.Logging.LogLevel.Debug, default(EventId), new Dictionary { { "ParameterCount", "1" } }, null, (s,ex) => "message with id and 1 property"); + } + public void LogWithScope() { using (_logger.BeginScope("scope1")) @@ -232,6 +249,14 @@ public void LogWithScope() } } + public void LogWithScopeParameters() + { + using (_logger.BeginScope(new[] { new KeyValuePair("scope1", "Hello") })) + { + _logger.LogDebug(20, "message with id and {0} parameters", 1); + } + } + public void Init() { _logger.LogDebug("init runner");