Nlog: MDLC vs LayoutRenderer

[gregkalapos]

Hi 👏

I'm working on a tracing library - the Elastic APM .NET Agent.

We plan to implement a feature that correlates traces to logs and we plan to also support NLog.

The way this works is that each time a trace is started we'd like to put the id of this trace to every single log that is created while the trace is active. If you direct your log messages to elasticsearch we also have a feature in Kibana (the UI) to jump from traces to logs and vice versa.

An active trace is for example an incoming request in an ASP.NET Core application - we have a middleware which must be registered first, it starts the trace and the trace is active as long as the middleware is not finished - every log during this should be tagged with the id of this trace.

But traces can be also started manually, so for example it can also be a random method in a simple console application. A trace can be active across multiple async methods.

_there are some more details here, but I don't wanna spam you with things that are probably not relevant_

Now, the question is: what is the best feature in NLog to use here to propagate the trace id. One approach would be to use a LayoutRenderer similar to TraceActivityIdLayoutRenderer

In our case it'd be something like this:

LayoutRenderer.Register("apmtraceId", (logEvent) =>
{
    if(Agent.IsConfigured)
        return Agent.Tracer?.CurrentTransaction?.TraceId;
    return string.Empty;
});

The other option would be to use MDLC, like this - we'd call this method each time the active trace changes.

public void ActiveTraceChanged(ITransaction transaction)
{
    if (!Agent.IsConfigured) return;
    var currentTransaction = Agent.Tracer.CurrentTransaction;
    if (currentTransaction == null)
    {
        MappedDiagnosticsLogicalContext.Clear();
        return;
    }
    MappedDiagnosticsLogicalContext.Set("Trace.Id", currentTransaction.Id);
}

The MDLC approach (based on the name and what I see in the docs) sounds better suited for what we do, but it's more complex, since we need to actively maintain the MDLC - the LayoutRenderer is simpler, but I'm not sure if it's safe to use for this.

So, which one would you suggest to use in our scenario? Or is there anything better to use for this?

Thanks!

_We discuss this here in our repo._

[welcome[bot]]

Hi! Thanks for opening your first issue here! Please make sure to follow the issue template - so we could help you better!

[snakefoot]

NLog MDLC / MappedDiagnosticsLogicalContext is the same as Serilog PushProperty

NLog LayoutRenderer is very equivalent to Serilog Enrichers. They allow you to capture context at the creation of the LogEvent.

Just like you have created Elastic.Apm.SerilogEnricher then I would create a Elastic.Apm.NLog-package that depends on NLog ver. 4.5.4:

Implemented something like this:

```c#
namespace NLog.LayoutRenderers
{
[LayoutRenderer("ElasticApmTransactionId")]
[ThreadSafe]
public class ApmTraceIdLayoutRenderer : LayoutRenderer
{
protected override void Append(StringBuilder builder, LogEventInfo logEvent)
{
if (!Agent.IsConfigured) return;
if (Agent.Tracer.CurrentTransaction == null) return;
builder.Append(Agent.Tracer.CurrentTransaction.Id.ToString());
}
}

[LayoutRenderer("ElasticApmTraceId")]
[ThreadSafe]
public class ApmTraceIdLayoutRenderer : LayoutRenderer
{
protected override void Append(StringBuilder builder, LogEventInfo logEvent)
{
if (!Agent.IsConfigured) return;
if (Agent.Tracer.CurrentTransaction == null) return;
builder.Append(Agent.Tracer.CurrentTransaction.TraceId.ToString());
}
}
}

Then you can reference it using `<contextproperty>` in in Targets that inherits from TargetWithContext/AsyncTaskTarget. Or you can add attribute to JsonLayout or property to XmlLayout. Ex:
```xml
<nlog>
<extensions>
   <add assembly="Elastic.Apm.NLog"/>
</extensions>
<targets>
<target type="file" name="logfile" fileName="myfile.txt">
    <layout type="jsonlayout">
        <attribute name="traceid" layout="${ElasticApmTraceId}" />
        <attribute name="transactionid" layout="${ElasticApmTransactionId}" />
    </layout>
</target>
</targets>
<rules>
    <logger name="*" minLevel="Trace" writeTo="logfile" />
</rules>
</nlog>

[gregkalapos]

Thank you @snakefoot, this sound very good!

Just to clarify one last thing, so all my doubts go away:

This means, it’s safe to assume that the LayoutRenderer is called synchronously right after the Write (or Information, Debug, etc) methods?

Meaning if a user writes logger.Information(“…”); then the LayoutRenderer is called directly without any threading, dispatching, Task scheduling whatsoever?

The reason I ask is because Agent.Tracer.CurrentTransaction reads the transaction from the async local storage, so that only works the way we want when the user code writing the log runs on the same thread or in the same Task (or in child tasks) as the Renderer.

Probably the answer to my question is yes, but I wanna make sure I don’t misunderstand.

Also, thanks for the code snippets! Super useful.

[snakefoot]

Yes. It will perform the capture right away. Just like the existing ${threadid}

---- Gergely Kalapos wrote ----

Thank you @snakefoothttps://github.com/snakefoot, this sound very good!

This means, it’s safe to assume that the LayoutRenderer is called synchronously right after the Write (or Information, Debug, etc) methods?

[gregkalapos]

Perfect, closing this as all questions are answered.

Thanks again!