Logging is one of the most essential parts of modern, real-life app development. If you’ve been writing code for any reasonable amount of time, then you’ve definitely handled logging in some way.
If you’re a .NET developer, then you’ve probably used some of the many famous logging frameworks available for use at this platform. Today’s post will cover one of these frameworks: log4net.
Getting started with logging, as well as the concept of a logging framework itself, can be a daunting task. This post features a gentle but complete introduction to log4net.
After following this tutorial, you’ll have a firm grasp on what’s log4net about, how to install log4net and use it. Also included are the most important best practices you should try to adopt. Let’s get started.
Before we dive into the nuts and bolts of how to use log4net, we need to understand what this thing is about.
The most popular logging framework for .NET platforms, log4net is not the only framework for .NET.
Logging frameworks are tools that dramatically reduce the burden of dealing with logs.
When you employ a framework, it takes care of many of the important yet annoying aspects of logging: where to log to, whether to append to an existing file or create a new one, formatting of the log message, and many more.
Adopting a logging framework makes writing your logs to different places easy, by simply changing your configuration.
You can write your .NET logs to a file on disk, a database, a log management system or potentially dozens of other places, all without changing your code.
Starting with log4net is as easy as installing a NuGet package. You can use the Visual Studio UI to search for log4net and install it, or just run this quick command from the Package Manager Console:
PM> Install-Package log4net
This is important because we need the log4net.config file to be copied to the bin folder when you build and run your app.
To get you started quickly, copy this log4net config and put it in your new log4net.config file. Doing so will log messages to both the console and a log file. We will discuss more about logging appenders further down.
<log4net>
<root>
<level value="ALL" />
<appender-ref ref="console" />
<appender-ref ref="file" />
</root>
<appender name="console" type="log4net.Appender.ConsoleAppender">
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date %level %logger - %message%newline" />
</layout>
</appender>
<appender name="file" type="log4net.Appender.RollingFileAppender">
<file value="myapp.log" />
<appendToFile value="true" />
<rollingStyle value="Size" />
<maxSizeRollBackups value="5" />
<maximumFileSize value="10MB" />
<staticLogFileName value="true" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date [%thread] %level %logger - %message%newline" />
</layout>
</appender>
</log4net>
The next thing we need to do is tell log4net where to load its configuration from so that it actually works. I suggest putting this in your AssemblyInfo.cs file.
You can find it under the Properties section in your project:
Add the following to the bottom of your AssemblyInfo file.
[assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config")]
Now you can modify your app to log something and run a test!
class Program
{
private static readonly log4net.ILog log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
static void Main(string[] args)
{
log.Info("Hello logging world!");
Console.WriteLine("Hit enter");
Console.ReadLine();
}
}
Appenders enable you to determine the destination of your log outputs. Among the standard appenders, the RollingFileAppender and ConsoleAppender are arguably the most favored.
For those who wish to view their log statements directly in the Visual Studio Debug window, bypassing the need to open a log file, employing the DebugAppender is recommended.
If you are using a Console, checkout the ColoredConsoleAppender.
Be sure to use Debug, Info, Warning, Error, and Fatal logging levels as appropriate within your code.
Don’t log everything as Debug. Be sure to think about how you will be viewing the logs and what you want to see later when coding your logging statements.
In your log4net configuration, you can define which log4net logging levels you wish to record.
These steps are really valuable if you want to specify only certain levels to be logged to a specific log appender or to reduce logging in production. Proper levels and filters also allow you to log more or less data without changing your code.
log4net levels:
Declaring any variable in your code has overhead. When doing some profiling sessions in the past to optimize code, I have noticed that the constructors on the LogManager object can use a lot of CPU.
Declare LogManager as static and use this little trick so you don’t have to hard code the class type.
private static readonly log4net.ILog log
= log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
From time to time, you may have problems with a specific appender or issues working with it.
Enabling internal log4net logging via your web.config file will help resolve these issues.
<configuration>
<appSettings>
<add key="log4net.Internal.Debug" value="true"/>
</appSettings>
</configuration>
You can then specify where the logging is written to.
<configuration>
...
<system.diagnostics>
<trace autoflush="true">
<listeners>
<add
name="textWriterTraceListener"
type="System.Diagnostics.TextWriterTraceListener"
initializeData="C:\tmp\log4net.txt" />
</listeners>
</trace>
</system.diagnostics>
...
</configuration>
Trying to query logs in SQL is very difficult if you log any real volume. You are much better off sending your logs to Elastic Search or a log management service that can provide full-text indexing and more functionality with your logs.
The last thing you want to do is send any sort of emails from an appender. They either get ignored over time or something starts throwing a lot of exceptions and then your app starts sending thousands of errors. Although, there is an SmtpAppender if you really want to do this.
If you want to send alerts about exceptions, send your exceptions to an error tracking product, like Retrace. The full lifecycle APM solution consolidates logs for enhanced troubleshooting, simplified error tracking and more.
Error tracking tools will also de-dupe your errors, so you can figure out when an error is truly new, track its history, and track error rates.
Capturing logs and logging them to a file on disk is great. But if you want to search your logs across multiple servers and applications, you need to send all of your logs to a central repository.
There are a lot of log management solutions that can help you with this, or you can even set up your own elasticsearch cluster for added search capabilities.
If you want to query all the files on disk, consider using VisualLogParser.
Configuring filters to block certain log messages is possible. Consider the following illustrations on how to apply filters based on the text within the log messages.
<filter type="log4net.Filter.StringMatchFilter"> <stringToMatch value="test" /> <!-- Can filter by string or regex --> </filter>
And here, you can filter by the log level:
<filter type="log4net.Filter.LevelRangeFilter"> <levelMin value="INFO" /> <levelMax value="FATAL" /> </filter>
If you need to do something that the usual appenders can’t do, look online or make one yourself.
For example, we once created an appender to send our logs to Azure Table storage. This helped us collect our logs in one place. Although we couldn’t search them easily because they weren’t fully indexed, we were still able to see them.
As an example of a custom appender, you can review the source code for our appender for sending logs to Retrace.
You can modify your configuration to change what fields are outputting and in what format using pattern layouts.
<appender name="LogFileAppender" type="log4net.Appender.RollingFileAppender">
<param name="File" value="stackify.log" />
<param name="AppendToFile" value="true" />
<rollingStyle value="Size" />
<maxSizeRollBackups value="10" />
<maximumFileSize value="10MB" />
<staticLogFileName value="true" />
<layout type="log4net.Layout.PatternLayout">
<param name="ConversionPattern" value="%-5p %d{MM-dd hh:mm:ss.ffff} [%thread] %m%n" />
</layout>
</appender>
Using the layout above, write the level (%p), current date time (%d), thread # (%thread), the message (%m) and a new line (%n). The -5 in the %-5p is to set the width of the field to 5 characters.
Here are additional fields you might consider logging, but be aware they can significantly impact your app’s performance and are not advisable for extensive logging in a production environment.
A layout like this:
<layout type="log4net.Layout.PatternLayout">
<param name="ConversionPattern" value="%-5p%d{ yyyy-MM-dd HH:mm:ss} – [%thread] %m method:%method %n stacktrace:%stacktrace{5} %n type:%type %n line: %line %n" />
</layout>
Produces a log message like this:
ERROR 2017-02-06 09:38:10 – [10] Error downloading web request method:ThrowWebException stacktrace:Microsoft.VisualStudio.HostingProcess.HostProc.RunUsersAssembly > System.AppDomain.ExecuteAssembly > System.AppDomain._nExecuteAssembly > ConsoleApplication1.Program.Main > ConsoleApplication1.Class1.ThrowWebException type:ConsoleApplication1.Class1 line: 26
You can also log custom fields to help give some more context about the user, customer or transaction related to the log statements.
The below example sets a custom property called customer. You can then modify your log4net pattern layout to include %property{customer} to output it in your logs.
log4net.ThreadContext.Properties["customer"] = "My Customer Name";
log.Debug("We are going to try and do a web request");
try
{
Class1.ThrowWebException();
}
catch (Exception ex)
{
log.Error("Error trying to do something", ex);
}
log.Debug("We are done with the web request");
Furthermore, objects can be designated within contexts to utilize what is referred to as active property values. As the log message is composed, the ToString() method is invoked, enabling dynamic operations.
This can be used to write transaction IDs to help correlate messages to a web request or transaction!
//Create our little helper class
public class ActivityIdHelper
{
public override string ToString()
{
if (Trace.CorrelationManager.ActivityId == Guid.Empty)
{
Trace.CorrelationManager.ActivityId = Guid.NewGuid();
}
return Trace.CorrelationManager.ActivityId.ToString();
}
}
In your global.asax or Startup.cs class, subscribe to an event for when a request first starts.
public override void Init()
{
base.Init();
this.Error += WebApiApplication_Error;
this.BeginRequest += WebApiApplication_BeginRequest;
this.EndRequest += WebApiApplication_EndRequest;
}
void WebApiApplication_BeginRequest(object sender, EventArgs e)
{
//set the property to our new object
log4net.LogicalThreadContext.Properties["activityid"] = new ActivityIdHelper();
log.Debug("WebApiApplication_BeginRequest");
}
DEBUG 02-06 02:51:58.6347 – a69640f7-d47d-4aa4-99c9-13cfd9ab93c2 WebApiApplication_BeginRequest DEBUG 02-06 02:51:58.6382 – a69640f7-d47d-4aa4-99c9-13cfd9ab93c2 Starting KitchenAsync - Call redis DEBUG 02-06 02:51:58.9315 – b8a3bcee-e82e-4298-b27f-6481b256b5ad Finished KitchenAsync DEBUG 02-06 02:51:59.1285 – a69640f7-d47d-4aa4-99c9-13cfd9ab93c2 Call Webclient DEBUG 02-06 02:51:59.1686 – 54218fab-bd1b-4c77-9ff8-ebef838dfb82 WebApiApplication_BeginRequest DEBUG 02-06 02:51:59.1746 – 54218fab-bd1b-4c77-9ff8-ebef838dfb82 Starting KitchenAsync - Call redis DEBUG 02-06 02:51:59.4378 – a69640f7-d47d-4aa4-99c9-13cfd9ab93c2 Finished KitchenAsync DEBUG 02-06 02:51:59.6450 – 54218fab-bd1b-4c77-9ff8-ebef838dfb82 Call Webclient DEBUG 02-06 02:51:59.9294 – 54218fab-bd1b-4c77-9ff8-ebef838dfb82 Finished KitchenAsync
You could use the same strategy as above to dynamically grab ASP.NET request info to add to your log message.
public class WebRequestInfo
{
public override string ToString()
{
return HttpContext.Current?.Request?.RawUrl + ", " + HttpContext.Current?.Request?.UserAgent;
}
}
void WebApiApplication_BeginRequest(object sender, EventArgs e)
{
log4net.LogicalThreadContext.Properties["activityid"] = new ActivityIdHelper();
log4net.LogicalThreadContext.Properties["requestinfo"] = new WebRequestInfo();
log.Debug("WebApiApplication_BeginRequest");
}
Typically, when you log an object, it gets serialized using the default rendering settings.
log.Debug(new {color="red", int1 = 1});
Output:
DEBUG 2017-02-06 15:07:25 – [8] { color = red, int1 = 1 }
But what if you want to log your entire log message as JSON?
There are several nuGet packages related to log4net and JSON, but the support and docs for all of them seem a little sketchy.
I would recommend just making your own JsonLayout class. There is a good sample on GitHub. You could then control exactly how you log the JSON and which fields you log.
Output from the GitHub JsonLayout:
{
"processSessionId" : "225ba696-6607-4abc-95f6-df8e0438e898",
"level" : "DEBUG",
"messageObject" : "Finished KitchenAsync",
"renderedMessage" : "Finished KitchenAsync",
"timestampUtc" : "2017-02-06T21:20:07.5690494Z",
"logger" : "WebApp2.Controllers.TestController",
"thread" : "69",
"exceptionObject" : null,
"exceptionObjectString" : null,
"userName" : "IIS APPPOOL\\WebApp2",
"domain" : "/LM/W3SVC/1/ROOT/WebApp2-10-131308895921693643",
"identity" : "",
"location" : "WebApp2.Controllers.TestController+d__27.MoveNext(C:\\BitBucket\\PrefixTests\\WebApp2\\Controllers\\TestController.cs:477)",
"pid" : 14428,
"machineName" : "LAPTOP-1UJ70V4E",
"workingSet" : 352481280,
"osVersion" : "Microsoft Windows NT 10.0.14393.0",
"is64bitOS" : true,
"is64bitProcess" : true,
"properties" : {
"requestinfo" : {},
"activityid" : {},
"log4net:UserName" : "IIS APPPOOL\\WebApp2",
"log4net:Identity" : "",
"log4net:HostName" : "LAPTOP-1UJ70V4E"
}
}
If you want to get the value of structured logging, you will want to send your logs to a log management tool that can index all the fields and enable powerful searching and analytics capabilities.
Learn more here: What is structured logging and why developers need it.
Log files can quickly become a spaghetti mess of log messages. Especially with web apps that have lots of AJAX requests that all do logging.
I highly recommend using Prefix, Stackify’s FREE .NET Profiler to view your logs per web request, along with SQL queries, HTTP calls and much more.
Logging is an essential part of modern software development.
Nowadays, deploying software to a production environment without implementing any form of logging is unimaginable. Doing so is equivalent to wandering through a vast city, at peak hour, with a blindfold on.
Software is a very complex thing.
When you release an app to an unfamiliar environment, you can’t be certain your app will work as planned.
If something goes wrong—and something always does—logging is one of the few ways you can use to “go back in time,” understand the problem, and fix it.
Today’s post discussed the log4net logging framework. You learned what a logging framework is and how it can help you avoid the hassle of creating a logging strategy. We also shared some best practices and tips to help you use log4net more effectively.
Thanks for reading, and we’ll see you in the next post.
Stackify's APM tools are used by thousands of .NET, Java, PHP, Node.js, Python, & Ruby developers all over the world.
Explore Retrace's product features to learn more.
If you would like to be a guest contributor to the Stackify blog please reach out to [email protected]
