In this episode we take a look at logging in ASP.NET Core, the builtin support and providers, as well as using third party implementations, namely NLog.
For the walk-through you can check the next video, but if you prefer a quick read, skip to the written synthesis.
The playlist for the whole series is here.
Logging is one of the basics when creating an application, as it allows us to have a glimpse of its behavior, not only in terms of problems it might run into, but also some information about what’s going on.
So far in this project, our “logging” has basically been
Console.WriteLine, which really isn’t a very good idea, as we want more control over logging behavior, like log levels and providers.
So let’s add some real logging to the project.
Using the builtin logging facilities
Setting up logging
Pretty similar to what we saw in the previous episode regarding configuration, the first thing we need to do is configure the logging providers we want to use (or as we’ll see, not really… again! 😛).
Like we did for configuration, we go into the
Program class and where we’re creating the
IWebHostBuilder, we can call the
ConfigureLogging method to setup the providers we want.
Going back to (by now well known)
CreateDefaultBuilder method, we can see it already configures some logging providers by default.
(complete source on GitHub, for ASP.NET Core 2.1)
By looking at the code we now know that:
- Configuration in the logging section will be used if existent (we’ll take a look at this in a bit)
- Console and debug providers are pre-configured
In this post we’ll mostly stick to the console (and later on, a file), so the default builder’s configuration is good to go.
Now lets replace the
Console.WriteLine calls we have in our code.
To log stuff, we must get an
ILogger<T> - or use an
ILoggerFactory<T>, but we’ll stick with
ILogger<T> for now - in the classes where we want to log. So if, for example, in the
GroupsController we wanted to add logs, we would add an
ILogger<GroupsController> and store it in a private field for usage in the actions. Right now, where we have already something being written to the console is in the
GroupsServiceDecorator, created in the
AutofacModule, so let’s take a look at that.
Rather simple stuff. In
GroupsServiceDecorator we get an
ILogger<GroupsServiceDecorator>, then use it in the methods. Just needed to add the dependency resolution in the
builder.RegisterDecorator above to pass the logger along.
If we run the application now, we get mostly the same we had, but with some extra info that comes from using a logger:
warn: CodingMilitia.PlayBall.GroupManagement.Web.IoC.AutofacModule.GroupsServiceDecorator ######### Helloooooo from GetById #########
Although we won’t get much advantage out of it right now, one thing we can do to improve the output of our logs is to make it structured logging friendly.
Structured logging (or semantic logging) means that besides the log message, some metadata is attached to each log, which may help in getting the most out of the logs, without lots of regular expressions or similar voodoos to extract the info needed. Let’s take the previous example of the
GroupsServiceDecorator, what if instead of just logging the message as is now, we use a provider that stores a JSON for each log, and besides the message, it stores the name of the decorated method with its semantic meaning, something like:
This would make it easier to find by decorated method name for example, count the number of times it was called and other things like that.
To achieve this, we replace the string interpolation used previously with the formatting capabilities provided by the logger’s methods:
Now, when in the future we configure the logger to output to someplace that supports it, we’ll have some better structured data to work with.
Changing log levels
So far the logs we’re creating are all warnings, but probably, for the kind of logs they are, they’re level should probably be
Trace or something like that. Haven’t used this yet because the default log level is
Information, so a
Trace wouldn’t be shown. Let’s change that.
appsettings.development.json, let’s add a section for logging, where we can configure
We can immediately see that not only we define a log level, but we can define it per namespace. So, the default log level will be
Debug, but namespaces starting with
System will only log
Information, namespaces starting with
Microsoft only allow
Warning or above and, finally, for the namespace
CodingMilitia.PlayBall.GroupManagement.Web.IoC (where the decorator exists) everything is logged, having
Trace as minimum level.
Now we can replace our
LogTrace and see it still showing up on the console.
trce: CodingMilitia.PlayBall.GroupManagement.Web.IoC.AutofacModule.GroupsServiceDecorator ######### Helloooooo from GetById #########
Another interesting feature we can use when logging are scopes. Scopes allow us to group a set of log calls, to which we can attach some data that’ll be always part of the log, without the need to add that information in every log invocation.
For us to see scopes in action, we need to enable then in the configuration for the console provider:
Just by doing this, we can see a difference when looking at the console logs, because ASP.NET Core makes use of this functionality:
trce: CodingMilitia.PlayBall.GroupManagement.Web.IoC.AutofacModule.GroupsServiceDecorator => ConnectionId:0HLIF66I6VVM5 => RequestId:0HLIF66I6VVM5:00000001 RequestPath:/groups/1 => CodingMilitia.PlayBall.GroupManagement.Web.Controllers.GroupsController.Details (CodingMilitia.PlayBall.GroupManagement.Web) ######### Helloooooo from GetById #########
Comparing with previous logs, we can see the extra couple of lines, with information about the request and controller that handles it.
Now let’s try adding a scope of ours.
GetAll method as an example, we create the scope using
_logger.BeginScope inside a
using statement, ensuring that only the logs created inside of it make use of the scope, including logs that are not directly inside the
using, but in code invoked there.
The scope might have a message as well as extra info associated with it, that’ll go along with every log in its context.
Also added another
_logger.LogTrace to the method, so we can see that both take the scope’s information along with them. The console output turns out as follows.
trce: CodingMilitia.PlayBall.GroupManagement.Web.IoC.AutofacModule.GroupsServiceDecorator => ConnectionId:0HLIF66I6VVM6 => RequestId:0HLIF66I6VVM6:00000001 RequestPath:/groups => CodingMilitia.PlayBall.GroupManagement.Web.Controllers.GroupsController.Index (CodingMilitia.PlayBall.GroupManagement.Web) => Decorator scope: GroupsServiceDecorator ######### Helloooooo from GetAll ######### trce: CodingMilitia.PlayBall.GroupManagement.Web.IoC.AutofacModule.GroupsServiceDecorator => ConnectionId:0HLIF66I6VVM6 => RequestId:0HLIF66I6VVM6:00000001 RequestPath:/groups => CodingMilitia.PlayBall.GroupManagement.Web.Controllers.GroupsController.Index (CodingMilitia.PlayBall.GroupManagement.Web) => Decorator scope: GroupsServiceDecorator ######### Goodbyeeeee from GetAll #########
Using third party loggers
Just as is the case for dependency injection, where we can use third party containers, we can also use third party logging libraries that may have some features we don’t get out of the box.
To see how we can use third party loggers, we’ll add NLog to our project, and replace the builtin logging providers.
Remove builtin providers and add NLog
To get the NLog dependency on our project,
dotnet add package NLog.Web.AspNetCore does the trick.
To replace the default logger with NLog, we head onto the
Program class and make a couple of changes to the
As we see above, we use
ConfigureLogging so we can clear the providers
WebHost.CreateDefaultBuilder added - we could keep them to use along with NLog, but that’s maybe a little more confusing than letting NLog handle everything. We also set the minimum log level to trace, so everything goes through to NLog, so its targets (we’ll see what they are in a moment) will handle logging only the things that should be logged.
Additionally, we must call
UseNLog on the
WebHostBuilder to setup NLog.
Now to configure NLog! Ideally we would create an
nlog.config file, but I’m just going to configure everything programmatically right now. For the recommended way to configure everything, check out NLog’s documentation.
To do this, I added a
ConfigureNLog method to the
Program class that’s called at the start of the application. In this method we setup NLog’s targets, which are like the ASP.NET Core logging providers, as we can set things like the console and files, specific log levels for each target, as well as specific log layouts for each.
I’d say that just by looking at the code above you can easily understand what’s going on. A couple of targets are created, console and file, each with different message layouts and log level rules, including (like we saw earlier for the builtin providers) making the log levels depend also on the namespace of the class that’s logging.
In regards to the layouts, most of the options used are pretty easy to understand, apart from
ndlc (which means “Nested Diagnostics Logical Context”) is the way to include the scope we talked earlier in the message.
A note on the
FileTarget - I really didn’t configure it as much as I should. For instance, defining when a new log file should be created (every new day, when it reaches a certain size, when the application restarts, etc) or when old ones are deleted is probably a good idea.
With this in place, we have everything working mostly as before, but having NLog in charge of the logs. The code that uses the logger doesn’t need any change. The only noticeable differences are the amount of messages we see, as I didn’t configure the log levels in exactly the same way and the layout of the message is also a bit different (and have colors because we used the
Console log sample
18:38:57 Warn ######### Helloooooo from GetById #########
File log sample
18:38:57 Warn ######### Helloooooo from GetById ######### ConnectionId:0HLIFS2291JCR RequestId:0HLIFS2291JCR:00000003 RequestPath:/groups/1 CodingMilitia.PlayBall.GroupManagement.Web.Controllers.GroupsController.Details (CodingMilitia.PlayBall.GroupManagement.Web)
That’s a wrap for another episode on the ASP.NET Core: From 0 to Overkill series. As usual, this is not everything there is to know about the topic, logging in this case, but it’s another stepping stone in our path to over-engineering 😆
The source code for this post is here.
Please send any feedback so I can improve and adjust the next episodes.
Thanks for stopping by, cyaz!