Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

MessageProperties - Allow capture of message properties (CaptureMessageProperties option) #148

Merged
merged 1 commit into from
Oct 15, 2017
Merged

MessageProperties - Allow capture of message properties (CaptureMessageProperties option) #148

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
131 changes: 113 additions & 18 deletions src/NLog.Extensions.Logging/NLogLogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 for splitting up in methods

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes the optimizations had suddenly made it a little convoluted

{
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>
Expand Down Expand Up @@ -165,6 +190,57 @@ 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)
{
try
{
property.Dispose();
}
catch
{
}
}
}
}
}

/// <summary>
/// Begin a scope. Use in config with ${ndlc}
/// </summary>
Expand All @@ -177,6 +253,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);
}
}
Expand Down
5 changes: 5 additions & 0 deletions src/NLog.Extensions.Logging/NLogProviderOptions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,11 @@ public class NLogProviderOptions
/// </summary>
public bool CaptureMessageTemplates { get; set; }

/// <summary>
/// Enable capture of properties from the ILogger-State-object, both in <see cref="Microsoft.Extensions.Logging.ILogger.Log"/> and <see cref="Microsoft.Extensions.Logging.ILogger.BeginScope"/>
/// </summary>
public bool CaptureMessageProperties { get; set; }

/// <summary>Initializes a new instance of the <see cref="T:System.Object" /> class.</summary>
public NLogProviderOptions()
{
Expand Down
34 changes: 33 additions & 1 deletion test/LoggerTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
using System;
using System.Collections.Generic;
using System.Linq;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
Expand Down Expand Up @@ -53,6 +54,24 @@ 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());
}

[Fact]
public void TestScopeProperties()
{
GetRunner().LogWithScopeParameters();

var target = GetTarget();
Assert.Equal("NLog.Extensions.Logging.Tests.LoggerTests.Runner|DEBUG|message with id and 1 parameters |0Hello", target.Logs.FirstOrDefault());
}

[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")]
Expand Down Expand Up @@ -168,7 +187,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;
}
Expand Down Expand Up @@ -224,6 +243,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"))
Expand All @@ -232,6 +256,14 @@ public void LogWithScope()
}
}

public void LogWithScopeParameters()
{
using (_logger.BeginScope(new[] { new KeyValuePair<string, object>("scope1", "Hello") }))
{
_logger.LogDebug("message with id and {0} parameters", 1);
}
}

public void Init()
{
_logger.LogDebug("init runner");
Expand Down
2 changes: 1 addition & 1 deletion test/nlog.config
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@
<targets>
<!-- write logs to file -->
<target xsi:type="Memory" name="target1"
layout="${logger}|${uppercase:${level}}|${message} ${exception}|${event-properties:EventId}${event-properties:ParameterCount}" />
layout="${logger}|${uppercase:${level}}|${message} ${exception}|${event-properties:EventId}${event-properties:ParameterCount}${mdlc:item=scope1}" />

</targets>

Expand Down