Today, we focus on a crucial yet often overlooked aspect of application development: logging. Specifically, we're going to explore logging in the .NET framework. Whether you're a seasoned C# developer or just starting your journey with .NET, this guide will showcase the types of errors that can creep up and harm the quality of your logs.
Logging is an essential part of any application. It's like an airplane's black box. When something goes wrong, the logs are often the first place developers look to understand what happened. Despite its importance, logging is frequently treated as an afterthought, implemented without proper planning or understanding. It is deeply frustrating to investigate a problem in your app only to discover that the logs do not give you the necessary information.
At Sonar, we help you find any issue in your code that could impair it and we help ensure you keep it clean. Ultimately, issues in your code impact the quality of the software you deliver, which you and your customers rely on daily. With our new rules targeting logging code in .NET, we guide you through correcting the problems we find and teach you how to avoid them in the future.
Why Sonar provides C# logging rules
The advent of structured logging, with fantastic .NET libraries such as Serilog, NLog, or Microsoft’s default logging library, made it possible to deal with vast amounts of logs optimally. If you are developing Cloud Native apps, the OpenTelemetry standard builds on your excellent logging foundation to provide full observability into your app, should you require it. All these great logging tools depend on your ability to avoid making mistakes when logging the required information.
Have you ever looked at logs, trying to understand the pathway to a specific bug in production, and found that the log message is wrong? Have you spent precious time implementing structured logging, ingesting your logs in a centralized system, only to find out the hard way that you did not log the details you needed? Suppose your system generates millions of logs daily, and your structured logging is not optimal. In that case, you could also be making your life much more difficult by hindering the search capabilities of your logging backend. Then, there is also that small mistake in your logging code. It lurked for months in the code and ultimately cost you weeks to diagnose another problem for a lack of good logs. It even required shipping a new version just so you could understand the problem, praying the issue would manifest itself again. Wouldn’t it have been more helpful if your build system told you in your pull request comments that you had made a small mistake when you first wrote the code? That’s what Sonar can do for you… avoid all this frustration and lost time.
It is very common to make such mistakes because most of the APIs are string-based. Copy-pasting-modifying is also heavily used when adding logging code because writing logging code is highly repetitive. This all leads to small, often overlooked issues that only reveal themselves months, if not years, later. These issues ultimately cost developers time and your company money. They reduce your ability to move quickly and to respond to incidents efficiently. They also reduce the effectiveness of both your infrastructure and your DevOps efforts.
Let’s look at some of the worst offenders among the mistakes you can make and how we find them for you in your code.
Message syntax and semantics
When logging in C#, ensuring that the code you write delivers what you expect is essential. This means making sure that the message is correct and contains the right information in the right location. Since the APIs rely on string and untyped arguments, it is surprisingly easy to make mistakes.
Let’s see what these errors look like.
Incorrect message syntax
Structured logging in .NET requires using a specific syntax. For example, let’s take the following code:
logger.LogError("Login failed for {User}. Invalid credentials", user);This is standard logging code for any application. The following mistake of omitting the closing curly bracket around the User property can easily persist undetected until it is too late:
logger.LogError("Login failed for {User. Invalid credentials", user);By omitting the closing curly bracket, the log output (plain text or structured JSON) will not contain the expected information.
Another common mistake of the above logging code is:
logger.LogError("Login failed for {User-Name}", user);In this case, the name of the placeholder is the culprit. Structured logging works by creating a property for each placeholder. The name of that property must abide by the standard syntax for identifiers in most languages. It must start with a letter or underscore and contain only letters, numbers, or underscores. The dash in the property name is incorrect, and since using dashes in names like filenames is common, it is a typical mistake developers make when writing code for logging.
Here, a typo is made, and a letter is used instead of a number for the alignment:
logger.LogDebug("Retry attempt {Cnt,r}", cnt);Sonar also detects missing format specifiers:
logger.LogDebug("Retry attempt {Cnt:}", cnt);Rule S6674 covers detecting all these problems.
Duplication of placeholders
In a logging message, all placeholders must be unique. Repeating the same name is a common mistake shown here in this code:
logger.LogDebug("User {Id} purchased order {Id}", user.Id, order.Id);Again, this ties back to the goal of structured logging, where the placeholder generates a specific property. If you use it multiple times, the results can vary depending on your logging framework. Some will only use the last value provided. Others will generate unique names behind the scenes. Rule S6677 detects this issue and warns you about it.
Incorrect order of placeholders
An annoying and common mistake is when the placeholders’ order does not match the argument order. This can easily happen when reworking your code. It is hard to detect when cursorily reading the code and can lead to more difficulties in diagnosing an issue in production.
Let’s look at an example:
logger.LogError("File {FileName} not found in folder {Path}", file.DirectoryName, file.Name, second);If you look closely, you will see that the intent is the opposite of what the code does because the arguments are in the wrong order. The outcome will be that:
- The message will be wrong.
- The fields generated by structured logging will also be wrong, ruining log querying capabilities.
Rule S6673 detects these types of errors. We discover the intent and match words in the placeholder’s name with words in the argument’s expression by building a list of words from camelcase, underscores, and dot characters and matching them.
Manually crafted messages
Before the advent of structured logging, crafting a logging message using string concatenation was normal. Creating logging messages became even easier with string interpolation in C#. For example, the following code is valid and will work:
logger.LogError("Login failed for {user}”);However, ILogger and all the logging backends use structured logging, allowing you to capture not only the message but also individual arguments in named fields, making the log much easier to query. It is much better to write the following:
logger.LogError("Login failed for {UserName}”, user);It is even more critical when emitting your logs through a standard like OpenTelemetry, where the back end should provide efficient storage and indexing of the fields. Rule S2629 detects this outdated pattern and shows you how to utilize your logging library fully.
Using the wrong overload
Most logging frameworks, including those used for logging in C#, have specific overloads that allow passing in a log level, an event ID, or an exception. If you call a method passing an overload value as a placeholder argument, you probably do not do what you intended.
For example, if you write this code:
logger.LogDebug("An exception occurred {Exception} with {EventId}.", ex, eventId); You should have written:
logger.LogDebug(eventId, ex, "An exception occurred.");Using the proper overloads should lead to much better outcomes when analyzing logs. Rule S6668 detects such errors.
Wrong logger category
ILogger comes with a generic flavor, indicating the type this logger is for. The log output will indicate which class generated a particular log entry by emitting the name of the type you passed in. This is extremely useful, but you can easily make a mistake when setting this up.
Look at this example:
public class EmailSender {
public EmailSender(ILogger<NotificationSender> logger){
_logger = logger;
}
}Here, we mistakenly specified the logger category as NotificationSender when the intent was to use EmailSender. This error probably came from copy-pasting the logger dependency from another class. You will not be able to pull the right messages by querying your logs for EmailSender. You will also not be able to adjust the logging level for EmailSender. Rule S6672 protects you from making this mistake.
A different take on this problem is the following:
class EmailSender
{
private readonly ILogger logger;
public EnclosingType(ILoggerFactory loggerFactory)
{
logger = loggerFactory.CreateLogger<NotificationSender>(); // Noncompliant
}
}The result is the same as the previous rule, with a loss of both querying capabilities and configurability. Rule S3416 protects you from this mistake.
Unlogged exception
When handling an exception, if you are emitting a log, it should contain the exception. In production, having the exception details with its message and, most importantly, its stack trace and potential inner exceptions are indispensable. Sooner or later, you will regret not including the full details of the exception. Because this is an exception handler, the frequency of logging the full exception should be low. Otherwise, it would not be an exception. In other words, the performance cost of logging a full exception should not be a concern.
Instead of writing:
try
{
DoSave();
return true;
}
catch(IOException)
{
logger.LogError("Saving failed.");
return false;
}You should write:
try
{
DoSave();
return true;
}
catch(IOException)
{
logger.LogError(exception, "Saving failed.");
return false;
}Rule S6667 detects the missing exception details so that your log can help you find your problem when the time comes.
Conventions and Consistency
Since logging is present in your entire codebase, you should set conventions. Setting conventions is vital to help relieve the brain of information overload. Proper conventions make the code base easier to understand because it allows you to “tune out” irrelevant details and concentrate on the core problem. Following conventions helps when modifying your code because your “muscle memory” will kick in. The objects will be where you expect them to be, and you will not have to hunt through the source to figure out where the logger is. This applies to both working alone and when working in a team.
Consistent placeholder naming
In a logging message, you should use a consistent naming convention for your placeholders, just as you do for your variables. Placeholders are akin to properties, and structured logging turns them into properties. For example, instead of writing:
logger.LogError("Login failed for {userName}”, userName);You should use PascalCase and write:
logger.LogError("Login failed for {UserName}”, userName);This little error can easily sneak in when using copy-paste on a variable name to create the placeholder or switching from interpolated string to structured logging. Rule S6678 protects you against that.
Logger storage fields
You should have a policy for naming your logger’s storage field. It will be easier to find because it stays the same across the code base. In a web project where each and every controller or service will have an injected logger, it’s best to always use the same field name for it. Visual Studio will even help you do that with its auto-completion helper.
Rule S6669 checks that the fields satisfy a regex. The default regex will allow the typical names (logger, _logger, Logger, _Logger…). I recommend changing that regex to restrict it even more. It should match your team’s conventions and allow only one form.
Another essential convention when using the Service Locator design pattern is that logger fields should be:
- private
- static
- read-only
Rule S1312, if activated, will enforce that policy. If you use dependency injection, this rule does not apply, as the field should not be static. It should still be marked private and read-only, though.
Performance and log file considerations
Trace.Write… methods
Logging goes back to the beginnings of the .NET Framework. Of course, today, we have ILogger and multiple choices for structured logging, but one should remember that options were more limited once upon a time. Legacy code bases will contain logging using the Trace and TraceSwitch class, and there are best practices to follow.
The Trace class offers different ways to write messages:
- TraceInformation, TraceWarning, TraceError
- Write, WriteIf, WriteLine, WriteLineIf
The main difference between these two options comes down to semantics. The first ones will write a trace with a specified level attached to it. The second set will just write a message. At first glance, Trace.WriteError() seems similar to Trace.WriteLineIf(switch.TraceError), but they are not. You should probably not use the Write… family of methods and stick to the first family.
Overlogging
There is such a thing as too much logging. Logging too much can lead to:
- Performance degradation
- Log file overload
- Code that is difficult to read
If your code contains a lot of logging entries, it will be challenging to read. Similarly, a log file with too many entries is more difficult to understand, especially for multithreaded code.
We provide rule S6664 to guard against this. This configurable rule will allow you to set a threshold for the number of times you can call a logging method in a given block.
For example, if you set it to two, it will raise an issue on the following code because the second code block has three calls:
void MyMethod(List<MyObject> items)
{
logger.Debug("The operation started");
foreach(var item in items)
{
logger.Information("Evaluating {Item}", item.Name);
var result = Evaluate(item);
logger.Information("Evaluating resulted in {Result}", result);
if (item.Name is string.Empty)
{
logger.Error("Invalid item name");
}
logger.Information("End item evaluation");
}
logger.Debug("The operation ended");
}This can easily be refactored as such:
void MyMethod(List<MyObject> items)
{
logger.Debug("The operation started");
foreach(var item in items)
{
logger.Information("Evaluating {Item}", item.Name);
var result = Evaluate(item);
if (item.Name is string.Empty)
{
logger.Error("Invalid item name");
}
logger.Information("End item evaluation with result {Result}", result);
}
logger.Debug("The operation ended");
}Another take on this problem is logging too many exceptions. We did say earlier that you should log exceptions, but sometimes, too much of a good thing can be harmful. If you log an exception when you catch it and then rethrow the exception, there is a very good chance it will be re-logged up the stack. You should either log the exception or rethrow it, but not both. An exception has a lot of information in it, and repeatedly logging the same exception can lead to a log file that is hard to use. Of course, there is no problem logging in a catch clause and rethrowing the exception if the log does not contain the exception details. Rule S2139 detects such cases.
What’s next?
There are many things to keep in mind when writing logging code. Sonar provides 15 rules to help you avoid a range of mistakes you might make, but this is far from the end of the subject.
If you are investigating how to deal with logging, read up on OpenTelemetry. This standard has emerged as the leading solution for application observability, especially for Cloud Native applications. All actors are adopting it, and it is infinitely configurable to suit your needs. We recommend evaluating emitting Traces. Distributed tracing is baked into the .NET runtime through the Activity class, and adding it to your application is a matter of calling a few methods. Most libraries and frameworks that you use already offer out-of-the-box support for it.
Don’t forget that Sonar helps you maintain Clean Code throughout your .NET codebase, with over 450 rules for C# and support for over 30 languages. We detect and help you resolve issues that impact your software's maintainability, security, and reliability.
If you are already a SonarCloud user, you can leverage our new logging rules today. These new C# logging rules will be available in the SonarQube 10.5 release and a future release of SonarLint for your preferred IDE.
If you have not used our products yet, the easiest way to try them is to install SonarLint for free in your IDE and analyze your code with SonarCloud. If your project is open-source, then SonarCloud is free of charge, so please try it out. The rules covered in this article only scratch the surface of what Sonar can do for you. If you prefer a self-managed solution under your control, then SonarQube is the better choice.
Now go write some Clean Code!