NLog EventProperties in .NET Core

Question

I'm using ILogger<MyController> to write logs using DI (see step 6)

I want to add traceId to all my logs in my controller automatically.

This is working:

logger.Info("Some log. TraceId:{traceId}", 123);

However, then I need to change all my log commands (a lot of them!), which is a pain.

If I do the following, it's not tread safe:

using NLog;
public class MyController : Controller
{
    private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
    public MyConstructor(Apilog apilog)
    {
        Logger.SetProperty("traceid", apilog.TraceId);
    }
}

Is there some way to use SetProperty with ILogger<MyController>?

Or some way of using NLog with SetProperty in a fast and thread safe way?

Many thanks in advance!

`Logger.SetProperty` is like a shotgun to your face, unless you really know what you are doing. You are right that it will behave very bad, when multiple threads are using the same Logger. — Rolf Kristensen, Feb 15 '20 at 07:13
Maybe consider adding extension-methods to your `Apilog`-class that takes Logger as parameter. Then you can implement the advanced version here: https://github.com/NLog/NLog.Extensions.Logging/wiki/NLog-properties-with-Microsoft-Extension-Logging#logtstate-advanced — Rolf Kristensen, Feb 15 '20 at 07:21
Alternative you can register a custom LayoutRenderer that works similar to `${activityid}` https://github.com/NLog/NLog/wiki/Trace-Activity-Id-Layout-Renderer and https://github.com/NLog/NLog/wiki/How-to-write-a-custom-layout-renderer — Rolf Kristensen, Feb 15 '20 at 10:03
My .net core startup.cs is calling a middleware app.UseMiddleware that inserts a logs before/after the actual controller call. In the middleware, if I add Trace.CorrelationManager.ActivityId = Guid.NewGuid(); before await _next.Invoke(httpContext); and add ${activityid} to my nlog.config it is working but I don't think it's thread safe (multiple threads would modify this value at the same time so the guid would "leak" between the threads). — user3401331, Feb 15 '20 at 10:41
Regarding the extension method, I'm not really sure how that would work. If it's anything like this example see "Consider adding a scope identifier to filter logs by scope" https://blog.rsuter.com/logging-with-ilogger-recommendations-and-best-practices/ then I would have to wrap the logger.LogInformation it in a using statement. Then I might as well use BeginScope and inject it there https://github.com/NLog/NLog.Extensions.Logging/wiki/NLog-properties-with-Microsoft-Extension-Logging#logtstate-advanced — user3401331, Feb 15 '20 at 10:44
Rolf Kristensen: Do you have an example for this extension method and how it's called? You have to specify the extension in Log Advanced example here: https://github.com/NLog/NLog.Extensions.Logging/wiki/NLog-properties-with-Microsoft-Extension-Logging#logtstate-advanced — user3401331, Feb 15 '20 at 10:47
`Trace.CorrelationManager.ActivityId` will work because the variable lives in thread execution context. And each thread have their own execution context (Updating one will not affect the others). The execution context can also travel if using async / await. — Rolf Kristensen, Feb 15 '20 at 11:10
Thanks a lot Rolf Kristensen! It's the way to go for sure. Just to clarify. "The execution context can also travel if using async / await." When thread A encounters var someValue = await SomeAyncMethod() using async/await , it goes back to the thread pool. Some thread (maby A, maby another thread) executes the SomeAyncMethod(). If SomeAyncMethod() has a Logger.LogInfo("something"), are you saying it would log the same ${activityid} value as A did? — user3401331, Feb 15 '20 at 13:31
Yes when A schedules a new task using async await or just Task.Run, then the new task will inherit a copy of A's execution context. Any changes the new task makes to its own copy will not affect the original execution context of A. — Rolf Kristensen, Feb 15 '20 at 13:35

Julian · Accepted Answer · 2020-03-26T12:52:05.113

2

When you share loggers between threads, then you could use WithProperty to ensure thread safeness.

Please note that WithProperty/SetProperty is only available on the Logger of NLog. (so not ILogger of Microsoft.Extensions.Logging`). See below.

Example:

using NLog;
public class MyController : Controller
{
    private static readonly Logger BaseLogger = LogManager.GetCurrentClassLogger(); 

    private readonly Logger Logger; // non static because of traceid. 
    public MyConstructor(Apilog apilog)
    {        
        Logger = BaseLogger.WithProperty("traceid", apilog.TraceId);
    }
}

Is there some way to use SetProperty with ILogger<MyController>?

There is no SetProperty on the ILogger interface of Microsoft.Extensions.Logging, but you could do this:

using (_logger.BeginScope(new[] { new KeyValuePair<string, object>("traceid", apilog.TraceId) }))
{
   _logger.LogDebug("Log message");
}

And use in your config: ${mdlc:traceid}. See more details and options here

edited Mar 26 '20 at 12:52

answered Feb 15 '20 at 02:24

Julian

33,915
22
119
174

GetCurrentClassLogger() is resource intensive so it's not best practise to use it as non-static property. _logger.BeginScope... would be less painful than to alter every Log.LogError statement and if would be thread safe for sure. – user3401331 Feb 15 '20 at 10:49
Updated answer for that. – Julian Feb 15 '20 at 11:21
2

@Julian, I am not sure I understand the BeingScope construct. I suppose it could be useful if I have multiple log statements in the same method. But what about across all methods in the controller? Is there any way to do this for the entire HTTP request? – e36M3 Mar 19 '21 at 19:21

NLog EventProperties in .NET Core

1 Answers1