Event Logging in .NET Core

Logging in any application is always a contentious issue with many developers rolling their own framework and tacking on third party libraries such as Nlog or Log4net. While these approaches are fine, Microsoft have come in and made logging a priority in ASP.net core. What that means is a standardized way of logging that is both simple and easy to get up and running, but also extensible when you have more complicated logging needs.

The Basics

This guide assumes you have a basic project up and running (Even just a hello world app), just to test how logging works. For getting up and running, we are going to use the debug logger. For that, you need to install the following Nuget package :

Install-Package Microsoft.Extensions.Logging.Debug

In your startup.cs file, in the Configure method, you need to add a call to AddDebug on your logger factory. This may already be done for you depending on which code template you are using, but in the end it should end up looking a bit like the following :

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
 loggerFactory.AddDebug();
 
 app.UseMvcWithDefaultRoute();
}

Let’s try this out first. Run your web project and view any URL. Back in Visual Studio you should view the “Output” window. If you can’t see it, go Debug -> Windows -> Output. After viewing any URL you should see something pretty similar to :

Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request starting HTTP/1.1 GET http://localhost:47723/api/home  
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executing action method LoggingExample.Controllers.HomeController.Get (LoggingExample) with arguments () - ModelState is Valid
Microsoft.AspNetCore.Mvc.Internal.ObjectResultExecutor:Information: Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action LoggingExample.Controllers.HomeController.Get (LoggingExample) in 11.8351ms
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 22.8292ms 200 text/html; charset=utf-8

The content isn’t too important at this stage, but the import thing is that you are seeing logging in action! Of course it is a bit verbose and over the top, but we will be able to filter these out later.

That sort of automatic logging is great, but what we really want is to be able to log things ourselves. Things like logging an exception or fatal error that someone should look into immediately. Let’s go into our controller. First we need to add a dependency on ILogger in our constructor and then we need to actually log something. In the end it looks a bit like this :

public class HomeController : Controller
{
 private readonly ILogger _logger;
 
 public HomeController(ILogger<HomeController> logger)
 {
 _logger = logger;
 }
 
 [HttpGet]
 public IActionResult Get()
 {
 _logger.LogInformation("Homepage was requested");
 try
 {
 throw new Exception("Oops! An Exception is going on!");
 }
 catch (Exception ex)
 {
 _logger.LogError(ex.ToString());
 }
 
 return Ok("123");
 }
}

Great, now when we go into this action what do we see in the debug window?

LoggingExample.Controllers.HomeController:Information: Homepage was requested
LoggingExample.Controllers.HomeController:Error: System.Exception: Oops! An Exception is going on!
   at LoggingExample.Controllers.HomeController.Get()

You will notice that our log messages are shown with the level that they are logged at, in this case Information and Error. At this point it doesn’t make too much a difference but it will do in our next section.

See how easy that was? No more fiddling around with nuget packages and building abstractions, the framework has done it all for you.

Logging Levels

The thing is, if we rolled this into production (And used a logger that pushes to the database), we are going to get inundated with logging about every single request that’s coming through. It creates noise that means you can’t find the logs you need, and worse, it may even cause a performance issue with that many writes.

An interesting thing about even the Microsoft packaged loggers is that there isn’t necessarily a pattern for defining their configuration. Some prefer full configuration classes where you an edit each and every detail, others prefer a simple LogLevel enum passed in and that’s it.

Since we are using the DebugLogger, we need to change our loggerFactor.AddDebug method a bit.

loggerFactory.AddDebug(LogLevel.Error);

What this says is please only log to the debug window errors we find. In this case we have hardcoded the level, but in a real application we would likely read an appSetting that was easily changeable between development and production environments.

Using the same HomeController that we used in the first section of this article, let’s run our app again. What do we see in the debug window?

LoggingExample.Controllers.HomeController:Error: System.Exception: Oops! An Exception is going on!
   at LoggingExample.Controllers.HomeController.Get()

So we see it logging our error message but not our information message or the system messages about pages being loaded. Great!

Again, It’s important to note that each logger may have their own configuration object that they use to describe logging levels. This can be a huge pain when swapping between loggers, but it’s all usually contained within your startup.cs.

Logging Filters

Most (if not all) loggerFactory extensions accept a lambda that allows you to filter out logs you don’t want, or to add extra restrictions on your logging.

I’ll change the AddDebug call to the following :

loggerFactory.AddDebug((category, loggingLevel) => category.Contains("HomeController"));

In this case, “category” stands for our logging category which in real terms is the full name (Namespace + Class) of where the logger is being used. In this case we have locked it down to HomeController, but we could just as easily lock it to “LoggingExample”, the name of this test app. Or “Controllers”, the name of a folder (And in the namespace) in our example app.

Under this example and running our code again, we see that we log everything from the controller (Information & Error), but we log nothing from the system itself (Page requests etc).

What you will quickly find is that this Lambda will get crazy big and hard to manage. Luckily the LoggerFactory also has an extra method to deal with this situation.

loggerFactory
 .WithFilter(new FilterLoggerSettings
 {
 {"Microsoft", LogLevel.None},
 {"HomeController", LogLevel.Error}
 
 })
 .AddDebug();

Using this, you can specify what level of logging you want for each category. LogLevel.None specifies that you shouldn’t log anything.

Enjoy !!