Nlog: Structured logging with property values from (some) context

[pardahlman]

Hello, project - thanks for all the great work you've put into making NLog compatible with structured logging 👍

I've used Serilog for some of my previous projects, and have found the LogContext invaluable when enriching log entries. I tend to add context properties early on (request id, correlation id, causation id...) and then add nested child context along the execution path. For some entries, I want one or more properties (from the context) to be rendered in my message template, especially in sinks/targets where the full context is not rendered.

Here's an example with the console output that describes the logging behavior

Log.Logger = new LoggerConfiguration()
    .Enrich.FromLogContext()
    .WriteTo.Console()
    .CreateLogger();

var logger = Log.ForContext<Program>();

using (LogContext.PushProperty("RequestId", Guid.NewGuid()))
{
    using (LogContext.PushProperty("ChildScope", 1))
    {
        logger.Information("Log for request {RequestId} in {ChildScope}");
        // outputs: Log for request abea8b03-81a0-4fe9-9d19-c13bbab9ebbb in 1
    }
    using (LogContext.PushProperty("ChildScope", 2))
    {
        logger.Information("Log for request {RequestId} in {ChildScope}");
        // outputs: Log for request abea8b03-81a0-4fe9-9d19-c13bbab9ebbb in 2
    }
}

I tried to achieve something similar with MappedDiagnosticsContext.SetScoped, but with no success. I think this will be a useful addition to NLog's structured logging, too. What do you think?

[snakefoot]

NLog MappedDiagnosticsLogicalContext is the same as Serilog PushProperty.

What fails to work when using MappedDiagnosticsLogicalContext.SetScoped and ${mdlc:item=String} ?

You can specify on the JsonLayout to includeMdlc="true"

[pardahlman]

Thanks for getting back to me. Are you suggesting to use a message template similar to this

logger.Information("Log for request ${mdlc:RequestId} in ${mdlc:ChildScope}");

I'm not a fan of this as it clutters the message template (makes it harder to read what the intended log entry is for)... also, not sure that it follows the message template specification for holes:

Hole ::= '{' ( '@' | '$' )? ( PropertyName | Index ) ( ',' Alignment )? ( ':' Format )? '}'

The "hole" should only contain the property name, optionally suffixed with @ or $ and optionally suffixed with alignment and format.

Looking forward hearing back from you!

[snakefoot]

Ohh sorry thought you had used NLog before, but it seems you should start here:

https://github.com/NLog/NLog/wiki/Tutorial
https://github.com/NLog/NLog/wiki/How-to-use-structured-logging

NLog works different than Serilog. NLog requires you to specify output at the NLog Target using layoutrenderers. Where Serilog requires you to gather the output at the logger-interface with enrichers.

```c#
using (MappedDiagnosticsLogicalContext.SetScoped("RequestId", Guid.NewGuid()))
{
using (MappedDiagnosticsLogicalContext.SetScoped("ChildScope", 1))
{
logger.Information("Log for request");
}
}

Then you can configure the NLog-target like this:

```xml
    <target xsi:type="File" name="jsonFile" fileName="c:\temp\nlog-json-${shortdate}.log">

      <layout xsi:type="JsonLayout" includeAllProperties="true" includeMdlc="true">
        <attribute name="time" layout="${longdate}" />
        <attribute name="level" layout="${level:upperCase=true}"/>
        <attribute name="Logger" layout="${logger}" />
        <attribute name="message" layout="${message:raw=true}" />
      </layout>

    </target>

[304NotModified]

I'm not a fan of this as it clutters the message template

Me too, therefore in NLog it's more natural to combine all the info in the config, see the excellent post of snakefoot.

[pardahlman]

Thanks @snakefoot - I have used NLog on multiple occations, even though it was a couple of years ago by now 😉. I can see how the code you wrote works, but it is not exactly what I'm asking for. When I wrote

I want one or more properties (from the context) to be rendered in my message template, especially in sinks/targets where the full context is not rendered.

I meant that I didn't want to use includeMdlc="true", but rather explicit render those that are part of my message template. An example is the console target, which I want to keep clutter-free (that is only render the formatted message).

To get back to my example, what I wanted to work was something like this

using (MappedDiagnosticsLogicalContext.SetScoped("RequestId", Guid.NewGuid()))
{
    using (MappedDiagnosticsLogicalContext.SetScoped("ChildScope", 1))
    {
          logger.Information("Log for request {RequestId} in {ChildScope}");
    }
}

Where {RequestId} and {ChildScope} should be rendered in the formatted message. Looking at the message template site again

Given a set of property values, and a message template, implementations should render the template by substituting property values into the locations of the corresponding named holes.

This leads me back to my original question: Is there a way to capture properties so that it can be rendered as properties in structured logging (without any non-standard prefix to the hole in the message template).

My apologies if this is documented somewhere, I've read the tutorial and the page on structured logging, but didn't find any information for this particular scenario.

Thanks!

[snakefoot]

@pardahlman How do you see the difference between a message-template that is missing its arguments, and a message-template that should capture its arguments from a "random" location ?

I don't think that we have any logic that auto-rewrites to this:
c# using (MappedDiagnosticsLogicalContext.SetScoped("RequestId", Guid.NewGuid())) { using (MappedDiagnosticsLogicalContext.SetScoped("ChildScope", 1)) { logger.Information("Log for request {RequestId} in {ChildScope}", MappedDiagnosticsLogicalContext.Get("RequestId"), MappedDiagnosticsLogicalContext.Get("ChildScope")); } }

I guess one could create special message-template-formatter that does this implicit, and register this a default.

[pardahlman]

So, the message template does not miss an argument, it is extracted from the "log context", which is a stack of properties that has been accumulated through the execution path as well as the arguments to the logger call. If you look at the Serilog snippet I posted in the original issue, the RequestId and ChildScope is extracted from this context rather than being explicitly passed to the logging call. (This is achieved as I'm enriching the logs from the log context - Enrich.FromLogContext())

This is what I'm asking for, and if I understood you correctly this is not supported.

[snakefoot]

Yes this has not been implemented

[pardahlman]

OK thanks for letting me know 👍 . As I said in the original post I really like this feature, but if this is something that isn't technically feasible or conceptually desired in the NLog project, you can close this issue.

Thanks again!

[snakefoot]

Simple workaround until something better comes, could be this:

```c#
public static class LoggerExtensions
{
public void InfoWithContext(this ILogger logger, string message, params object[] list)
{
if (logger.IsInfoEnabled)
{
switch (list.Length)
{
case 1:
logger.Info(string.Concat(message, " {", list[0], "}"), MappedDiagnosticsLogicalContext.Get(list[0]));
break;
case 2:
logger.Info(string.Concat(message, " {", list[0], "}", " {", list[1], "}"), MappedDiagnosticsLogicalContext.Get(list[0]), MappedDiagnosticsLogicalContext.Get(list[1]));
break;
default:
// TODO Be clever with a StringBuilder
break;
}
}
}
}

Then you can do this:

```c#
using (MappedDiagnosticsLogicalContext.SetScoped("RequestId", Guid.NewGuid()))
{
    using (MappedDiagnosticsLogicalContext.SetScoped("ChildScope", 1))
    {
          logger.InfoWithContext("Log for request", "RequestId", "ChildScope");
    }
}

[304NotModified]

Yes this has not been implemented

Indeed, and still I think it should be in the config, e.g. layout="${message} ${mdc:RequestId} in ${mdc:ChildScope}"

Why repeat the info, which is already available, in the message?

[pardahlman]

@304NotModified because I want the specified properties to be an _integrated part_ of the formatted message, not just text appended to the end of the log entry. The properties to be rendered in the message is driven by the message template used in the call, not a application-wide configuration. So for example, if the message template contains RequestId, it should be rendered in the output, if not it shouldn't be part of the rendered message.

Makes sense? I feel that I lack the NLog terminology for making myself clear. Let me know if I should elaborate what I mean

[snakefoot]

@pardahlman Makes sense? I feel that I lack the NLog terminology for making myself clear. Let me know if I should elaborate what I mean

I understand what you want. But it doesn't seem like how structured logging works in Microsoft Extension Logging or specified in messagetemplates.org.

But I guess you can do whatever you want by just implementing your own formatter and assign to NLog LogEventInfo.MessageFormatter. Maybe a nice hobby-project for the cold winter :)

[pardahlman]

But it doesn't seem like how structured logging works in Microsoft Extension Logging or specified in messagetemplates.org.

Perhaps you are right, even though there is no syntax constraints on messagetemplates.org for _where_ the properties come from or that they needs to be passed to the logger method as arguments 😛

Anyhow, I have too little time and too many hobby projects but perhaps this could be one... don't hold your breath, though 😉

[304NotModified]

I assume your question has been answered, if not, please let us know!