Categories
c#

Adding the Username to the Logs for every ASP.NET Core Request with NLog

I’m currently investigating how we port a large ASP.NET application to ASP.NET Core, and one of the things I had to figure out this morning was how to include information about the logged-in user in our logs.

The most important value to collect is the username, but I also need to be able to collect other information from the session at some point.

In the original ASP.NET app we did some slightly questionable HttpContext.Current access inside the logging providers, which I didn’t love.

In ASP.NET Core however, I can combine the use of the middleware system with NLog to add this information to my logs in a much better/easier way.

Adding NLog to my App

To add NLog to my ASP.NET Core app, I just followed the basic instructions at https://github.com/NLog/NLog/wiki/Getting-started-with-ASP.NET-Core-2 to get up and going (that guide tells you what you need to put in your Program and Startup classes to wire everything up).

I then updated the default HomeController to write a log message in the index page:

public class HomeController : Controller
{
public ILogger<HomeController> Logger { get; }
public HomeController(ILogger<HomeController> logger)
{
Logger = logger;
}
public IActionResult Index()
{
Logger.LogInformation("User loaded the home page");
return View();
}
// and the rest..
}
view raw HomeController.cs hosted with ❤ by GitHub

So when I launch my app, I get my log messages out (this is just the basic ASP.NET Core site template):

Adding our Username to Log Events

First up, I’m just going to add an extremely basic action to my HomeController that will sign me in with a test user (I’ve already set up the Startup class configuration to add cookie authentication):

public async Task<IActionResult> SignMeIn()
{
// Just do a real basic login.
var claims = new List<Claim>
{
new Claim(ClaimTypes.Name, "ajevans"),
new Claim("FullName", "Alistair Evans"),
new Claim(ClaimTypes.Role, "Administrator"),
};
var claimsIdentity = new ClaimsIdentity(claims, "AuthCookie");
await HttpContext.SignInAsync(
"AuthCookie",
new ClaimsPrincipal(claimsIdentity));
Logger.LogInformation("Signed in {user}", claimsIdentity.Name);
return RedirectToAction(nameof(Index));
}
view raw HomeController.cs hosted with ❤ by GitHub

Now we can do the middleware changes (this is the important bit). In the Startup class’ Configure method, we have an additional Use method:

public void Configure(IApplicationBuilder app)
{
app.UseStaticFiles();
app.UseCookiePolicy();
app.UseAuthentication();
app.Use(async (ctxt, next) =>
{
if(ctxt.User == null)
{
// Not logged in, so nothing to do.
await next();
}
else
{
// Set a scoped value in the NLog context, then call the next
// middleware.
var userName = ctxt.User.Identity.Name;
using (MappedDiagnosticsLogicalContext.SetScoped("userName", userName))
{
await next();
}
}
});
app.UseMvc(routes =>
{
routes.MapRoute(
name: "default",
template: "{controller=Home}/{action=Index}/{id?}");
});
}
view raw Startup.cs hosted with ❤ by GitHub

The MappedDiagnosticsLogicalContext class is an NLog class that lets you provide values that are scoped to the current async context. These values are attached to every log event raised inside the using block. The call to next() inside our using means that the entirety of the middleware pipeline (from that point onwards) has the userName property attached to it.

Displaying the Username in the Log

The last part of this is to update our nlog.config to display the username.

To do this, we use the MDLC Layout Renderer to pull the userName property out of the log event, by adding ${mdlc:userName} inside our layout:

<!-- the targets to write to -->
<targets>
<!-- write logs to file -->
<target xsi:type="File" name="allfile" fileName="c:\temp\nlog-all-${shortdate}.log"
layout="${longdate} | ${uppercase:${level:padding=5}} | ${mdlc:userName} | ${logger} | ${message} ${exception:format=tostring}" />
<!-- another file log, only own logs. Uses some ASP.NET core renderers -->
<target xsi:type="File" name="ownFile-web" fileName="c:\temp\nlog-own-${shortdate}.log"
layout="${longdate} | ${uppercase:${level:padding=5}} | ${mdlc:userName} | ${logger} | ${message} ${exception:format=tostring} | url: ${aspnet-request-url} | action: ${aspnet-mvc-action}" />
</targets>
view raw nlog.config hosted with ❤ by GitHub

Now, if we start the application, and log in, we get our username in each log event!

2019-09-07 10:40:15.4822 | DEBUG | | Main.Program | Starting Application | url: | action:
2019-09-07 10:40:18.5081 | INFO | | Main.Controllers.HomeController | Home page | url: https://localhost/ | action: Index
2019-09-07 10:40:40.3932 | INFO | | Main.Controllers.HomeController | Signed in ajevans | url: https://localhost/Home/SignMeIn | action: SignMeIn
2019-09-07 10:40:40.4028 | INFO | ajevans | Main.Controllers.HomeController | Home page | url: https://localhost/ | action: Index
2019-09-07 10:40:58.8799 | INFO | ajevans | Main.Controllers.HomeController | Home page | url: https://localhost/ | action: Index
2019-09-07 10:41:05.0707 | INFO | ajevans | Main.Controllers.HomeController | Home page | url: https://localhost/ | action: Index
view raw logcontent.log hosted with ❤ by GitHub

The real bonus of assigning the username inside the middleware though is that the extra detail gets added to the internal Microsoft.* logs as well:

2019-09-07 10:41:05.0707 | INFO | | Microsoft.AspNetCore.Hosting.Internal.WebHost | Request starting HTTP/1.1 GET https://localhost:5001/
2019-09-07 10:41:05.0707 | INFO | ajevans | Microsoft.AspNetCore.Routing.EndpointMiddleware | Executing endpoint 'Main.Controllers.HomeController.Index (Main)'
2019-09-07 10:41:05.0707 | INFO | ajevans | Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker | Route matched with {action = "Index", controller = "Home"}. Executing controller action with signature Microsoft.AspNetCore.Mvc.IActionResult Index() on controller Main.Controllers.HomeController (Main).
2019-09-07 10:41:05.0707 | INFO | ajevans | Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker | Executing action method Main.Controllers.HomeController.Index (Main) - Validation state: Valid
2019-09-07 10:41:05.0707 | INFO | ajevans | Main.Controllers.HomeController | Home page
2019-09-07 10:41:05.0779 | INFO | ajevans | Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker | Executed action method Main.Controllers.HomeController.Index (Main), returned result Microsoft.AspNetCore.Mvc.ViewResult in 5.3381ms.
2019-09-07 10:41:05.0779 | INFO | ajevans | Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor | Executing ViewResult, running view Index.
2019-09-07 10:41:05.0779 | INFO | ajevans | Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor | Executed ViewResult - view Index executed in 1.978ms.
2019-09-07 10:41:05.0779 | INFO | ajevans | Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker | Executed action Main.Controllers.HomeController.Index (Main) in 8.4146ms
2019-09-07 10:41:05.0779 | INFO | ajevans | Microsoft.AspNetCore.Routing.EndpointMiddleware | Executed endpoint 'Main.Controllers.HomeController.Index (Main)'
2019-09-07 10:41:05.0779 | INFO | | Microsoft.AspNetCore.Hosting.Internal.WebHost | Request finished in 10.42ms 200 text/html; charset=utf-8
2019-09-07 10:41:05.1352 | INFO | | Microsoft.AspNetCore.Hosting.Internal.WebHost | Request starting HTTP/1.1 GET https://localhost:5001/favicon.ico
2019-09-07 10:41:05.1679 | INFO | | Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware | Sending file. Request path: '/favicon.ico'. Physical path: 'D:\AzureDevOps\ISA-Prototyping\Main\wwwroot\favicon.ico'
2019-09-07 10:41:05.1685 | INFO | | Microsoft.AspNetCore.Hosting.Internal.WebHost | Request finished in 33.3657ms 200 image/x-icon
view raw mslogcontent.log hosted with ❤ by GitHub

You’ll notice that not all the log messages have a username value. Why is that?

The reason is that those log messages come from middleware that occurs earlier in the pipeline than our middleware that assigns the username, so those log events won’t contain that property.

In conclusion…

So, you’ve seen here how to use the NLog MappedDiagnosticsLogicalContext class and ASP.NET Core middleware to add extra information to all the log messages for each request. Don’t forget that you can add as much information to the log as you need, for example you could pull some user session state value out of the Session and add that too.