NLog properties with Microsoft Extension Logging

Message Template

Microsoft Extension Logging supports message templates for structured logging:

_logger.LogDebug("Logon from {userid}", request.UserId);

The NLog Logging Provider will capture these as NLog LogEventInfo.Properties, which can be included in NLog target output using ${event-properties} renderer. Or using the advanced NLog Layouts JsonLayout, XmlLayout, Log4jLayout etc.

This can be abused (but it is not optimal):

var properties = new Dictionary<string, object>();
properties["userid"] = request.UserId; // Add as many as you like
var stringBuilder = new StringBuilder("MyLogMessage");
foreach (var property in properties)
    stringBuilder.Append(" - {").Append(property.Key).Append('}');
_logger.LogDebug(stringBuilder.ToString(), properties.Values.ToArray());

BeginScope

NLog.Extensions.Logging ver. 1.0 supports async properties captured from the BeginScope input parameter:

using (_logger.BeginScope(new[] { new KeyValuePair<string, object>("userid", request.UserId) }))
{
   _logger.LogDebug("Logon from {0}", request.UserId);
}

It is possible to output the context-state from BeginScope using these NLog LayoutRenderers:

• ${scopeproperty} - Output a single property from ScopeContext
• ${scopenested} - Output entire nested context from ScopeContext
• ${scopetiming} - Output timings from ScopeContext
• ${all-event-properties:includeScopeProperties=true} - Output all properties from ScopeContext
• JsonLayout with IncludeScopeProperties = true - Output all properties from ScopeContext in JSON

Notice with .NET5 / .NET6 then Microsoft have started using System.Diagnostics.Activity.Current for context-state instead of BeginScope. If you have legacy code that depend on the old way, then NLog can simulate it by setting NLogProviderOptions.IncludeActivityIdsWithBeginScope to true.

Log<TState> Simple

Microsoft Extension Logging can log any kind of TState-object, when using the direct Log-method instead of the extension methods.

NLog.Extensions.Logging ver. 1.0 will attempt to cast the TState-object into IEnumerable<KeyValuePair<string, object>>, and if successful then include them as NLog LogEventInfo.Properties.

This can be used to create a custom logevent object that contains both a message and properties.

class MyLogEvent : IEnumerable<KeyValuePair<string, object>>
{
    List<KeyValuePair<string, object>> _properties = new List<KeyValuePair<string, object>>();

    public string Message { get; }
                
    public MyLogEvent(string message)
    {
        Message = message;
    }

    public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
    {
        return _properties.GetEnumerator();
    }

    IEnumerator IEnumerable.GetEnumerator() { return GetEnumerator(); }

    public MyLogEvent WithProperty(string name, object value)
    {
        _properties.Add(new KeyValuePair<string, object>(name, value));
        return this;
    }

    public static Func<MyLogEvent, Exception, string> Formatter { get; } = (l, e) => l.Message;
}

_logger.Log( Microsoft.Extensions.Logging.LogLevel.Debug,
             default(EventId),
             new MyLogEvent($"Logon from {request.UserId}").WithProperty("userid", request.UserId),
             (Exception)null,
             MyLogEvent.Formatter );

These properties can then be extracted using the ${event-properties} renderer.

Log<TState> Advanced

Combines structured logging message template with additional properties. It wraps the message formatter from Microsoft Extension Logging, and allows injection of extra properties:

public class MyLogEvent2 : Microsoft.Extensions.Logging.ILogger, IReadOnlyList<KeyValuePair<string, object>>
{
    readonly string _format;
    readonly object[] _parameters;
    IReadOnlyList<KeyValuePair<string, object>> _logValues;
    List<KeyValuePair<string, object>> _extraProperties;

    public MyLogEvent2(string format, params object[] values)
    {
        _format = format;
        _parameters = values;
    }

    public MyLogEvent2 WithProperty(string name, object value)
    {
        var properties = _extraProperties ?? (_extraProperties = new List<KeyValuePair<string, object>>());
        properties.Add(new KeyValuePair<string, object>(name, value));
        return this;
    }

    public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
    {
        if (MessagePropertyCount == 0)
        {
            if (ExtraPropertyCount > 0)
                return _extraProperties.GetEnumerator();
            else
                return System.Linq.Enumerable.Empty<KeyValuePair<string, object>>().GetEnumerator();
        }
        else
        {
            if (ExtraPropertyCount > 0)
                return System.Linq.Enumerable.Concat(_extraProperties, LogValues).GetEnumerator();
            else
                return LogValues.GetEnumerator();
        }
    }

    IEnumerator IEnumerable.GetEnumerator()
    {
        return GetEnumerator();
    }

    public KeyValuePair<string, object> this[int index]
    {
        get
        {
            int extraCount = ExtraPropertyCount;
            if (index < extraCount)
            {
                return _extraProperties[index];
            }
            else
            {
                return LogValues[index - extraCount];
            }
        }
    }

    public int Count => MessagePropertyCount + ExtraPropertyCount;

    public override string ToString() => LogValues.ToString();

    private IReadOnlyList<KeyValuePair<string, object>> LogValues
    {
        get
        {
            if (_logValues == null)
                Microsoft.Extensions.Logging.LoggerExtensions.LogDebug(this, _format, _parameters);
            return _logValues;
        }
    }

    private int ExtraPropertyCount => _extraProperties?.Count ?? 0;

    private int MessagePropertyCount
    {
        get
        {
            if (LogValues.Count > 1 && !string.IsNullOrEmpty(LogValues[0].Key) && !char.IsDigit(LogValues[0].Key[0]))
                return LogValues.Count;
            else
                return 0;
        }
    }

    void Microsoft.Extensions.Logging.ILogger.Log<TState>(Microsoft.Extensions.Logging.LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
    {
        _logValues = state as IReadOnlyList<KeyValuePair<string, object>> ?? Array.Empty<KeyValuePair<string, object>>();
    }

    bool Microsoft.Extensions.Logging.ILogger.IsEnabled(Microsoft.Extensions.Logging.LogLevel logLevel)
    {
        return true;
    }

    IDisposable Microsoft.Extensions.Logging.ILogger.BeginScope<TState>(TState state)
    {
        throw new NotSupportedException();
    }

    public static Func<MyLogEvent2, Exception, string> Formatter { get; } = (l, e) => l.LogValues.ToString();
}

_logger.Log( Microsoft.Extensions.Logging.LogLevel.Debug,
             default(EventId),
             new MyLogEvent2("Logon from {userid}", request.UserId).WithProperty("ipaddress", request.IpAddress),
             (Exception)null,
             MyLogEvent2.Formatter );

The properties can then be extracted using the ${event-properties} renderer.