MessageProperties - Allow capture of message properties through ILogg…

…er-state and ILogger-scope
NLog · Oct 15, 2017 · cf94721 · cf94721
1 parent f4bf50d
commit cf94721
Show file tree

Hide file tree

Showing 3 changed files with 138 additions and 19 deletions.
diff --git a/src/NLog.Extensions.Logging/NLogLogger.cs b/src/NLog.Extensions.Logging/NLogLogger.cs
@@ -40,25 +40,12 @@ public void Log<TState>(Microsoft.Extensions.Logging.LogLevel logLevel, EventId
             var messageTemplate = _options.CaptureMessageTemplates ? state as IReadOnlyList<KeyValuePair<string, object>> : 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 <see cref="NLogProviderOptions.EventIdSeparator"/>
-                var eventIdPropertyNames = _eventIdPropertyNames ?? new Tuple<string, string, string>(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<string, string, string>(
-                        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 <see cref="NLogProviderOptions.EventIdSeparator"/>
+                var eventIdPropertyNames = _eventIdPropertyNames ?? new Tuple<string, string, string>(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<string, string, string>(
+                        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>(TState state, LogEventInfo eventInfo)
+        {
+            if (state is IEnumerable<KeyValuePair<string, object>> messageProperties)
+            {
+                foreach (var property in messageProperties)
+                {
+                    if (string.IsNullOrEmpty(property.Key))
+                        continue;
+
+                    eventInfo.Properties[property.Key] = property.Value;
+                }
+            }
+        }
+
         /// <summary>
         /// Is logging enabled for this logger at this <paramref name="logLevel"/>?
         /// </summary>
@@ -165,6 +190,51 @@ private static LogLevel ConvertLogLevel(Microsoft.Extensions.Logging.LogLevel lo
             }
         }
 
+        class ScopeProperties : IDisposable
+        {
+            List<IDisposable> _properties;
+            List<IDisposable> Properties { get { return _properties ?? (_properties = new List<IDisposable>()); } }
+
+            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();
+                    }
+                }
+            }
+        }
+
         /// <summary>
         /// Begin a scope. Use in config with ${ndlc} 
         /// </summary>
@@ -177,6 +247,25 @@ public IDisposable BeginScope<TState>(TState state)
                 throw new ArgumentNullException(nameof(state));
             }
 
+            if (_options.CaptureMessageProperties)
+            {
+                if (state is IEnumerable<KeyValuePair<string, object>> 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
@@ -27,6 +27,11 @@ public class NLogProviderOptions
         /// </summary>
         public bool CaptureMessageTemplates { get; set; }
 
+        /// <summary>
+        /// Enable conversion of 
+        /// </summary>
+        public bool CaptureMessageProperties { get; set; }
+
         /// <summary>Initializes a new instance of the <see cref="T:System.Object" /> class.</summary>
         public NLogProviderOptions()
         {

diff --git 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<ILoggerFactory>();
 
-            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<string, object> { { "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<string, object>("scope1", "Hello") }))
+                {
+                    _logger.LogDebug(20, "message with id and {0} parameters", 1);
+                }
+            }
+
             public void Init()
             {
                 _logger.LogDebug("init runner");