Defensive logging on ASP.NET Core
ASP.NET Core logging framework is intelligent one and it supports also so called defensive logging that helps us to have intelligent logs but still avoid putting additonal load to system when it’s not needed. This blog post is short overview of defensive logging on ASP.NET Core.
- ASP.NET Core: How log filtering works
- ASP.NET Core: Implementing Syslog logger
- File logging on ASP.NET Core
- Defensive logging on ASP.NET Core
Defensive logging is supported by ASP.NET Core logging framework. Let’s suppose there’s some information-level logging code that asks additional information from service or data layer.
public IActionResult ConfirmOrder(int id)
{
var order = _orderService.GetById(id);
var user = _userService.GetById(User.Identity.Name);
_logger.LogInformation("User " + user.FullName + " confirmed order " + order.OrderNo);
... //
}
Although the code forms a nice logging message with all information needed the message is useless when information level is not in use. Logging framework doesn’t throw any exceptions but message is not logged. Some expensive code is running on server but the outcome of it is nothing.
Let’s try now to avoid this situation and let’s write to log only if information level is allowed. For this ILogger provides IsEnabled() method.
public IActionResult ConfirmOrder(int id)
{
var order = _orderService.GetById(id);
if (_logger.IsEnabled(LogLevel.Information))
{
var user = _userService.GetById(User.Identity.Name);
_logger.LogInformation("User " + user.FullName + " confirmed order " + order.OrderNo);
}
... //
}
Now information-level message is created only when information-level logging is enabled. This code saves one expensive round-trip to service layer in production environment.
Wrapping up
ASP.NET Core logging framework provides us with intelligent logging options like defensive logging. For test and QA environments we can enable more logging and we can completely switch off same powerful logging code depending on if given log level is enabled.
Hi, Your RSS feed shows 2016’s posts.
Thanks for pointing out the issue, Saeid. I will fixit. It takes some reconfiguring of blog engine.
And feed works again!
I don’t really agree here :
– even if it is not the point, Information should be logged in production, you *do* want info about your production, don’t you ? If this is too much, it is probably a hint that something should be debug-level (and you *hope* you won’t need to Debug in production).
– it is too easy to use this (anti IMO) pattern when not needed, which could actually worsen performance if the message is “free” (think const string), but the check is not (you need to do it twice now).
– there is an intrinsic smell when you repeat the log level, and could get them out of sync.
– often one-line logs can go along the flow of reading very well, perhaps replacing a comment ; this is much less true when you add the “if” (especially with braces)
– for the rare case where you really want to avoid the cost, you can use lazy evaluation, maybe something like _logger.Log(…, new Lazy(ExpensiveMethod), (l, _) => l.Value). This is more complex, but you it makes it clear that something is expensive, and you probably won’t see it copy/pasted when it doesn’t make sense.