Last updated: December 15, 2023
In the world of software development, logging often takes a backseat to unit testing and documentation. However, logging is a critical tool for debugging in production, providing insights into the real-world use of your application. When things stop working, it’s the data in the logs that both the development and operations teams use to troubleshoot the issue and quickly fix the problem.
Logs offer a way to record and track the events happening within your application, which is different from crash reporting. While crash reporting captures information at the time of an application failure, logging provides ongoing insights into the application’s behavior, helping to identify issues before they lead to a crash. This makes logging an essential proactive tool for maintaining the health and performance of your application.
Why Do We Need Logging in C# Applications?
Logging in C# applications is vital for various reasons. It helps debug issues, monitor the application’s health, and understand user behavior. Effective logging can save a lot of time during the development phase and helps quickly identify and fix production issues. It acts as a window into the application, providing visibility into its state and behavior, which is crucial for maintaining a healthy and reliable software environment.
Now, having understood the importance of logging, let’s move on to some best practices to ensure that we make the most out of it.
1. Don’t Reinvent the Wheel
While writing your own logging library from scratch is possible, most developers benefit from using a battle-tested option. Fortunately, Microsoft bundles a decent native library called TraceSource with the .NET SDK. To use TraceSource, you need to enable this feature in your configuration file, which is named application.config and located in the same folder as your application executable.
You can enable TraceSource by adding the code below to your application.config file:
<configuration>
<system.diagnostics>
<sources>
<source name="TraceTest"
switchName="sourceSwitch"
switchType="System.Diagnostics.SourceSwitch">
<listeners>
<add name="console"
type="System.Diagnostics.ConsoleTraceListener">
<filter type="System.Diagnostics.EventTypeFilter"
initializeData="Error"/>
</add>
<add name="myListener"/>
<remove name="Default"/>
</listeners>
</source>
</sources>
<switches>
<add name="sourceSwitch" value="Error"/>
</switches>
</system.diagnostics>
</configuration>
Once TraceSource is enabled, use this tool to write messages to the console like this:
class TraceTest
{
private static TraceSource ts = new TraceSource("TraceTest");
static void Main(string[] args)
{
ts.TraceEvent(TraceEventType.Error, 1, "Error message.");
ts.Close();
return;
}
}
2. Write Logs to Files, Not the Console
Logging to the console is useful, but ephemeral. What if you need to run a series of debug tests and compare the results, or maintain an event log? Writing log messages to different locations allows you to route each message to the most appropriate place(s).
TraceSource easily meets these needs. This logging library writes its messages to a listener object which then sends those messages to a predetermined location, such as the console, the Windows Event Log, or a file.
To add a listener that writes to a file, add this code to your configuration:
<configuration>
<system.diagnostics>
<trace autoflush="false" indentsize="4">
<listeners>
<add name="myListener" type="System.Diagnostics.TextWriterTraceListener" initializeData="TextWriterOutput.log" />
<remove name="Default" />
</listeners>
</trace>
</system.diagnostics>
</configuration>
This snippet adds a listener object called myListener and writes your messages to a log file titled TextWriterOutput.log. Then you can use the Trace class to write text to the file:
Trace.TraceInformation("Test message.");
// You must close or flush the trace to empty the output buffer.
Trace.Flush();
It’s also possible to dynamically add listeners at run time. This method is perfect for avoiding unnecessary overhead by only enabling logging when specific code paths are hit, such as the first time an error condition occurs.
The following code example shows how to dynamically add a new listener to the Trace.Listeners collection instead of using the static configuration file:
Trace.Listeners.Add(new TextWriterTraceListener("TextWriterOutput.log", "myListener"));
Trace.TraceInformation("Test message.");
// You must close or flush the trace to empty the output buffer.
Trace.Flush();
The .NET framework provides a whole host of listener classes for sending log messages to various destinations in a range of formats. You can check out the TraceListener Class documentation for more details.
3. Use A Third-Party Logging Library
The TraceSource library provided with the .NET SDK is useful in lots of situations, but ultimately, it’s a library focused on tracing and debugging, not logging. This means that TraceSource is missing the kinds of high-level APIs you’d expect in a standard logging framework.
Libraries such as such as Log4Net, Nlog, and serilog can handle the heavy lifting involved with the advanced features of System.Diagnostic.Tracesource so you don’t have to. Which library you choose will depend on your unique needs, though they are all similar in functionality for the most part. For our examples, we’ll use log4net.
As with the TraceSource library, you need to configure Log4Net in your app’s configuration file. Here’s a sample configuration that creates a logger that writes to a file and rolls it—moves the current file and creates a new empty one—whenever the file reaches 1MB in size.
<configuration>
<configSections>
<section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
</configSections>
<log4net>
<!-- In log4net, output destinations are known as appenders —>
<!-- Roll the file when it reaches 1MB -->
<appender name="LogFileAppender" type="log4net.Appender.RollingFileAppender">
<!-- Specify which file to write to -->
<param name="File" value="myLoggerFile.log"/>
<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
<appendToFile value="true" />
<rollingStyle value="Size" />
<!-- How many log files should we keep? -->
<maxSizeRollBackups value="2" />
<!-- Roll to a new file when current one hits 1MB -->
<maximumFileSize value="1MB" />
<staticLogFileName value="true" />
<!-- The format of each line in the log -->
<layout type="log4net.Layout.PatternLayout">
<param name="ConversionPattern" value="%d [%t] %-5p %c %m%n"/>
</layout>
</appender>
<!-- Set root logger level to INFO and appender to LogFileAppender -->
<root>
<level value="INFO" />
<appender-ref ref="LogFileAppender" />
</root>
</log4net>
</configuration>
The log4net configuration documentation provides more details on each configuration element and its attributes.
With the configuration file written, you can now write messages to myLoggerFile.log using the following code:
class LogTest
{
private static readonly ILog log = LogManager.GetLogger(typeof(LogTest));
static void Main(string[] args)
{
XmlConfigurator.Configure();
log.Info("Info message");
}
}
Thanks to the layout element in the configuration file, the log messages contain far more context is possible with TraceSource.
2023-12-14 00:39:10, 092 [1] INFO ConsoleProject.LogTest Hello World!
This log message provides us with a timestamp, the thread, the logging level, the class that wrote the message, and the log message itself. While not bad, it would be better if we could filter messages so that we only see the ones we’re interested in.
4. Make Use of Logging Levels
One of the most useful features of a logging library like log4net is the ability to ignore messages that are unimportant for a specific scenario. For example, when debugging your application in a pre-production environment you probably want to see all the log messages of DEBUG priority and above. Conversely, you definitely don’t want to see those messages when the application is running in production because they can obscure far more important messages.
log4net offers the following log levels, in increasing order of priority: ALL, DEBUG, INFO, WARN, ERROR, FATAL, OFF. The ALL level logs everything and the OFF level logs nothing. You can assign these log levels to each logger in your configuration file. Any message sent at a lower priority than the configured level will be ignored.
The advantage here is that you can configure the logging levels directly in your configuration file, and you don’t need to modify your code to change the types of log messages you care about; customizing your logs for production simply requires a separate config file.
To assign an output destination for your messages based on the logging level, create multiple appenders in your config file. For example, this configuration creates two loggers: one that sends all messages at or above INFO to info.log and a second logger that sends messages at or above ERROR to error.log.
<log4net>
<appender name="File1Appender" type="log4net.Appender.FileAppender">
<file value="info.log" />
<appendToFile value="true" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date %message%newline" />
</layout>
</appender>
<appender name="File2Appender" type="log4net.Appender.FileAppender">
<file value="error.log" />
<appendToFile value="true" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date %message%newline" />
</layout>
</appender>
<root>
<level value="INFO" />
<appender-ref ref="File1Appender" />
</root>
<logger name="error" />
<level value="ERROR" />
<appender-ref ref="File2Appender" />
</log4net>
Each file is written by a separate logger, so you need to use both inside of your code:
ILog Log = LogManager.GetLogger(typeof(LogTest));
ILog ErrorLog = LogManager.GetLogger("error");
Log.Info("Debug message");
ErrorLog.Error("Error message"));
While using more than one logger for small code bases is manageable, things quickly get out of hand as application size grows and as the number of loggers increase. A far more maintainable solution is to add filters.
5. Control Log Messages With Filters
The log4net package provides a number of filters that can finely control which messages are logged by which appenders. Here are a few examples of existing filters:
- log4net.Filter.DenyAllFilter – deny all messages
- log4net.Filter.StringMatchFilter – match messages containing a string
- log4net.Filter.LevelRangeFilter – match messages within a range of log levels
It’s not hard to think of uses for each of these options, and log4net.Filter.StringMatchFilter in particular is useful for sending log messages from specific application modules to a dedicated destination.
But it’s the last filter in the list that we’ll use to improve the config file from the previous section. By filtering messages based on their log level, one logger can send messages to multiple destinations.
The following example configuration sends messages at or above INFO to the info.log file but only messages at ERROR and FATAL to error.log.
<log4net>
<appender name="File1Appender" type="log4net.Appender.FileAppender">
<file value="info.log" />
<appendToFile value="true" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date %message%newline" />
</layout>
</appender>
<appender name="File2Appender" type="log4net.Appender.FileAppender">
<file value="error.log" />
<appendToFile value="true" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date %message%newline" />
</layout>
<filter type="log4net.Filter.LevelRangeFilter">
<levelMin value="ERROR" />
<levelMax value="FATAL" />
</filter>
</appender>
<root>
<level value="INFO" />
<appender-ref ref="File1Appender" />
<appender-ref ref="File2Appender" />
</root>
</log4net>
Now all messages can be written to the root logger, which will in turn forward those messages to the appenders, and the appenders will either ignore those messages or write them to a file based on the message’s log level.
6. Log Contextual and Diagnostic Data
Using the standard contextual items available within the app, such as the timestamp, provides much-needed context to our log message. But what if you need specific data from a class or method? What if you need to know the parameters of a request for your web app? There’s a whole host of details that could be useful, from user location to HTTPRequest parameters.
With frameworks such as log4net, there’s no need to place the burden on developers to add all of those details to each log message—log4net can add them automatically. That’s because log4net provides a class, LogicalThreadContext, which lets you store event-specific data and print it in your log files. To use this, update the conversionPattern element in your configuration file to include the “%property{data}” pattern.
For example, the following code stores a user ID in the “user” property which you can print in your log files by adding “%property{user}” to your conversionPattern.
log4net.LogicalThreadContext.Properties["User"] = User;
Log.Debug(“Found new user”);
7. Use Structured Logging
Using the best practices covered so far, it’s now possible to write log messages filled with rich, contextual data. The next and final step is to use structured logging. Logs containing structured data are easily filtered by log management tools such as SolarWinds® Papertrail™ and SolarWinds Loggly®, which makes it easier to search through your log data when hunting for clues to help diagnose application issues.
Frustration-free log management. (It’s a thing.)
Aggregate, organize, and manage your logs with PapertrailIn particular, log4net offers a JSON package, log4net.Ext.Json, which lets you log any object as JSON by serializing that object. To write JSON to your logs, add log4net.Ext.Json as a serialized layout to your appender.
<appender...>
<layout type='log4net.Layout.SerializedLayout, log4net.Ext.Json'>
</layout>
</appender>
As a result, writing the following DEBUG message:
log.Debug("Created a user", new { User=”user005”,CreatedBy=”prod-0001”});
Now displays this very parseable log message:
{"User":"user005", "CreatedBy":"prod-0001"}
Conclusion
Logging is a powerful tool for both development and production debugging. To ensure your application provides the level of logging necessary for your development and operations teams to track down and fix bugs quickly, follow these steps:
- Instead of reinventing the wheel, use an existing logging framework such as TraceSource or log4net.
- Use context-rich logging so that you’ll have all the information you might need when troubleshooting.
- Make your logs easily parseable by other tools, by writing structured logs.
Be mindful of the potential drawbacks of logging, such as performance impacts and the risk of exposing sensitive information. Ensure to implement proper log management practices to mitigate these issues.