Nlog: What to use instead of MappedDiagnosticsLogicalContext in ASP.NET CORE?

[Hussein-Dahir]

Hi,

I am using NLog in a web server written in ASP.NET CORE 2.2 to log every http request to Database.

I am doing this by adding only few logging statement in my middleware, something like this:

```c#
public class MyRequestMiddleware {

public MyRequestMiddleware (
RequestDelegate next,
ILoggerFactory loggerFactory,)
{
_next = next;
_logger = loggerFactory.CreateLogger("My Logger");
}

public async Task InvokeAsync(HttpContext context){
try {
await _next(context);
.
.
_logger.LogInformation(new EventId(eventID, eventName), logMessage);
}
catch (CustomException1 e) {
.
.
_logger.LogError(new EventId(eventID, eventName), logMessage);
}
.
.
catch (Exception e) {
.
.
_logger.LogCritical(new EventId(eventID, eventName), e, logMessage);
}
finally
{
// clear NLog MappedDiagnosticsContext from any stored data
NLog.MappedDiagnosticsContext.Clear();
}
}
}

In My Controllers, I may add some extra data to get logged using MappedDiagnosticsContext, and I am handling those in my CustomLoggingTarget.

Everything was working fine, until I used MappedDiagnosticsContext in API with some async operations (reading & writing to DB).

```c#
NLog.GlobalDiagnosticsContext.Set("argument1", argument1);

// async query to DB here

NLog.GlobalDiagnosticsContext.Set("argument2", argument2);

In such a case, argument 2 only is getting logged, with argument1 getting ignored.

In my research, I found that using MappedDiagnosticsLogicalContext instead of MappedDiagnosticsContext will fix this issue, but unfortunately, MappedDiagnosticsLogicalContext is not supported in ASP.NET CORE.

I saw the Properties way in EventProperties Layout Renderer, but this is not applicable in my case.

Gdc layout renderer worked fine, but I am afraid that it may make some problems for me for a parallel threads (requests) web server.

I finally found, AspNetItem-layout-renderer, but is this thread-safe? Can I use it for async Task-support?

[snakefoot]

MappedDiagnosticsLogicalContext is fully support on NetCore. Make sure to use NLog ver 4.5 or NLog ver. 4.6 (Do not use NLog 5.0-beta since it is abandoned)..

How did you come to the conclusion that MappedDiagnosticsLogicalContext is not available on NetCore?

Make sure to change your layoutrenderer from ${mdc} to ${mdlc} to get the correct output.

See also: https://github.com/NLog/NLog/wiki/LogEvent-Context-Information

[Hussein-Dahir]

@snakefoot Thanks for your reply.
In this MDLC Layout Renderer Docs, it says that MDLC is "Supported in .NET 4.0 and 4.5.", which made me think that it is supported in ASP.NET Standard only.

Anyway, I tried again, and found out that using
MappedDiagnosticsLogicalContext.Set("PropertyName", "PropertyValue");
Inside my middle-ware (where I have my logging sentences) works fine and ${mdlc} catches data correctly in my custom target, but using it inside any of my controllers doesn't work fine, ${mdlc} keeps giving null! no idea why!

MappedDiagnosticsContext.Set("PropertyName", "PropertyValue"); was working fine, wherever I use it! (but without async-Task support for sure, so I can't keep using it).

Do you have any idea what may cause such a problem?

PS: I am using a custom target that extends AsyncTaskTarget, and I am using JsonLayout inside it
(tried to set IncludeMdlc = true for JsonLayout, but nothing changed).

[snakefoot]

Wiki says that MDLC is "Supported in .NET 4.0 and 4.5."

Yes the supported platform details needs a refresh after NetCore (And removal of NetCompact).

but using it inside any of my controllers doesn't work fine, ${mdlc} keeps giving null! no idea why!

Not that skilled with transfer of context in middleware, controllers etc in ASP.NET.Core applications. Maybe @304NotModified knows more about it. Or you can ask on StackOverflow.

Btw. if you are using Microsoft Extension Logging. Then you can also use BeginScope to create MDLC-properties. See also https://github.com/NLog/NLog.Extensions.Logging/wiki/NLog-properties-with-Microsoft-Extension-Logging#beginscope

[Hussein-Dahir]

@snakefoot Thanks for your reply again, I don't use Microsoft Extension Logging, not sure if it will help in my case.

I will try StackOverFlow, and hope @304NotModified have an answer for that.

[304NotModified]

Yes the supported platform details needs a refresh after NetCore (And removal of NetCompact).

FYI, I removed that sentence.
Platform support is visible on https://nlog-project.org/config/ (see dropdown)

Anyway, I tried again, and found out that using
MappedDiagnosticsLogicalContext.Set("PropertyName", "PropertyValue");
Inside my middle-ware (where I have my logging sentences) works fine and ${mdlc} catches data correctly in my custom target, but using it inside any of my controllers doesn't work fine, ${mdlc} keeps giving null! no idea why!

That's strange! It should work, are you sure you're in the same request?

another option is to add the context on HttpContext.Items. This isn't builtin NLog, so you need a custom renderer. (PS, made https://github.com/NLog/NLog.Web/pull/9 years ago, but never got merged)

[Hussein-Dahir]

@304NotModified Yes I am sure
It was working fine with MDC (but MDC was losing some data in async methods)

I just changed
MappedDiagnosticsContext.Set("PropertyName", "PropertyValue");
to
MappedDiagnosticsLogicalContext.Set("PropertyName", "PropertyValue");

in middle-ware & all controllers

and ${mdc} to ${mdlc} in my Custom Target

and now only data comes from middle-ware only, all controllers data are lost (async APIs).

please note that I am using AsyncTaskTarget, maybe this issue occurs in this Target Type?

Moreover, I found a similar old issue here

[Hussein-Dahir]

OK, found it, just made a non-async API, and tried MappedDiagnosticsLogicalContext in it and it worked perfectly !

MappedDiagnosticsLogicalContext is not working in any async API! (at least with AsyncTaskTarget), Please fix!

[304NotModified]

MappedDiagnosticsLogicalContext is not working in any async API! (at least with AsyncTaskTarget), Please fix!

Could you please setup a small demo application for this?

[snakefoot]

@Hussein-Dahir Updated the unit-test for AsyncTaskTarget, and cannot reproduce your issue. The MDLC-state is correctly transfered to the async-task and captured by the Target. See also #3309

So please create a small demo to look at.

[Hussein-Dahir]

@snakefoot @304NotModified here you go, I set up a small demo for that:
https://github.com/Hussein-Dahir/nlog-mdlc-issue-reproduce-demo

In MyMiddleWare, I have the following:

public async Task InvokeAsync(HttpContext context)
{
    var eventID = Guid.NewGuid().ToString() + "-" + DateTime.UtcNow.Ticks.ToString();

    try
    {
        await _next(context);

        if (!NLog.MappedDiagnosticsLogicalContext.Contains("recordId"))
        {
            NLog.MappedDiagnosticsLogicalContext.Set("recordId", 200);
        }

        _logger.LogInformation(new EventId(0, eventID), "log msg");
    }
    catch (Exception e)
    {
        NLog.MappedDiagnosticsLogicalContext.Set("customMsg", "Exception logged in MiddleWare");
        _logger.LogCritical(new EventId(0, eventID), e, e.Message);
    }
    finally
    {
        //clear NLog MappedDiagnosticsLogicalContext from any stored data
        //NLog.MappedDiagnosticsLogicalContext.Clear();
    }
}

and in TodoController, I have this async API:

[HttpGet]
public async Task<ActionResult<List<TodoItem>>> GetAll()
{
    NLog.MappedDiagnosticsLogicalContext.Set("recordId", 100);
    NLog.MappedDiagnosticsLogicalContext.Set("customMsg", "logged in GetAll API");

    return await _context.TodoItems.ToListAsync();
}

now, when I hit GetAll API, I should have the following in my logs:
recordId = 100
customMsg = "logged in GetAll API"

but what I am getting is the following:
recordId = 200
customMsg = null

that is, data set in MappedDiagnosticsLogicalContext in the TodoController, wasn't passed correctly to the logger.

[snakefoot]

Think I understand what you are doing:

1. Task1 Enters public async Task InvokeAsync(HttpContext context)
2. Task1 Updates its local context by setting MDLC-recordId to 100
3. Task1 Schedules Task2 using await _next(context); (Task1 transfers MDLC-context to Task2)
4. Task2 Enters public async Task<ActionResult<List<TodoItem>>> GetAll()
5. Task2 Updates its local context by setting MDLC-recordId to 200 and completes.
6. Task1 Continues and performs logging of its local context (MDLC-recordid is still 100)

Any changes Task2 makes to its own local context will not affect the local context of Task1. This is how async Task state is designed.

If Task1 was scheduling 100 sub-tasks in parallel and all of them updated their local-context then it would cause congestion if they should also update the local context of Task1.

You can make Task2 schedule a Task3 (Task2 transfer MDLC-context to Task3), and let Task3 do the logging.

[Hussein-Dahir]

@snakefoot
Thanks for clarifying that, but why everything works fine when using MDC instead of MDLC in this example?

[snakefoot]

When using Tasks, then one is just using ThreadPool-threads. So there is a high chance of different tasks running on the same thread, or reusing a thread for the next task:

Here is an example:

1. Thread1-Task1 Enters public async Task InvokeAsync(HttpContext context)
2. Thread1-Task1 Updates its local context by setting MDC-recordId to 100
3. Thread1-Task1 Schedules Task2 using await _next(context);
4. Thread2-Task2 Enters public async Task<ActionResult<List<TodoItem>>> GetAll()
5. Thread2-Task2 Updates its local context by setting MDC-recordId to 200 and completes.
6. Thread2-Task1 Continues and performs logging of its local context (MDC-recordId is 200)

So yes MDC will work sometimes. But one is not guaranteed how the ThreadPool assigns Threads to the different Tasks.

[Hussein-Dahir]

@snakefoot thanks again,

But, when changing MappedDiagnosticsLogicalContext to MappedDiagnosticsContext, what happened with me was as follows (by debugging):

public async Task InvokeAsync(HttpContext context) will run await _next(context);

await _next(context); will schedule public async Task<ActionResult<List<TodoItem>>> GetAll()

public async Task<ActionResult<List<TodoItem>>> GetAll() will set MDC-recordId to 100

when returning to public async Task InvokeAsync(HttpContext context), no update to MDC-recordId will occur due to this if statement (checked that while debugging):

if (!NLog.MappedDiagnosticsContext.Contains("recordId"))
{
   NLog.MappedDiagnosticsContext.Set("recordId", 200);
}

So, MDC-recordId won't change in middle-ware (value will stay 100), and this will get logged.

But anyway, I think I get your point.

However, I tried to use HttpContext.Items instead of MDC or MDLC, alongside with ${aspnet-item:variable=recordId} Layout Renderer, and everything worked perfectly ! sync & async !

I think this method is thread-safe, since HttpContext.Items scope is the request.

Gets or sets a key/value collection that can be used to share data within the scope of this request.

[snakefoot]

Yes having a shared dictionary like aspnet- items. Will allow you to transfer context state forward and backward between tasks

One more might get surprises when having many tasks concurrently sharing (and updating) the same state.

[Hussein-Dahir]

@304NotModified @snakefoot Thanks for your help, both of you.

[mariusGundersen]

So if I understand this correctly, mdlc is not guaranteed to transfer logical context between tasks? Is there any way to have this guarantee?

[304NotModified]

@mariusGundersen MappedDiagnosticsLogicalContext is safe, MappedDiagnosticsContext isn't when using tasks.

If you have more questions, please open a new issue (and reference this one) thanks!

[snakefoot]

@mariusGundersen Please see my response to #3547

[aaronkitchen]

With lack of much posted resolutions regarding MappedDiagnosticsContext and MappedDiagnosticsLogicalContext functionality issues I thought I'd share, even on this old thread. Using .NET Core 5 and Blazor (Server), we have an app authenticating the user with Okta and needed to pull the user's email address as a means of a scoped identification for our needs when logging.

We set the DB field configs in nlog.config. One of them was for a user session parameter:

<parameter name="@userSession" layout="${mdc:email}" />

In code in a service IClaimsTransformation class conducting TransformAsync() after user authentication in Okta, we attempted to set the @userSession email by calling MappedDiagnosticsContext.SetScoped("email", emailAddressVar). But, any logging that would happen left empty strings in the user session column in the DB log table.

I ran across the note about "autoReload", which had been set "true" initially in our config. Setting autoReload="false" and using MappedDiagnosticsContext.SetScoped("email", emailAddressVar) then started working properly.

[snakefoot]

@aaronkitchen Thank you for your report of what worked for you. Sounds strange that autoreload should affect MappedDiagnosticsContext or MappedDiagnosticsDiagnosticContext.

Have you seen that NLog.Web.AspNetCore ver. 4.10 can now render User-Claim-Details directly without help from MDC / MDLC. See also: https://github.com/NLog/NLog/wiki/AspNet-User-Claim-layout-renderer

[aaronkitchen]

@snakefoot Awesome! Thanks for the tip. Coincidentally, I was toggling the autoReload to see if that actually "triggered" the behavior of the MDC.Set and, sadly, haven't been able to get it to work since.

However, I've installed the 4.10 package per your recommendation, and it works well with the <parameter name="@userSession" layout="${aspnet-user-claim:ClaimTypes.Email}" /> nlog.config entry. Sincere Thanks!

[aaronkitchen]

@snakefoot question regarding "aspnet-user-claim" render: this appeared to work fine in the development environment. But, we deployed to production using IIS web server and noted we lost the "aspnet-user-claim" functionality. The other template markers seem to work fine. Wondering what the difference could be.

<parameter name="@userSession" layout="${aspnet-user-claim:ClaimTypes.Email}" /> <parameter name="@logged" layout="${date}" /> <parameter name="@level" layout="${level}" /> <parameter name="@message" layout="${message}" /> <parameter name="@callSite" layout="${callsite:filename=false}" /> <parameter name="@exception" layout="${exception:format=@}" />

[snakefoot]

@aaronkitchen No idea. Never used aspnet-user-claim. Just implemented it based on the API. Maybe check the NLog InternalLogger for issues (internalLogLevel = Debug).

Btw. please create new issue instead of piggy-backing on existing issues.