If you’ve been writing code for any reasonable amount of time, then it’s virtually impossible that you haven’t handled logging in any way, since it’s one of the most essential parts of modern, “real life” app development.
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—and also the concept of a logging framework—can be a daunting task. This post will feature 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 it and use it, and what the most important best practices are that 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 why this thing is about.
So, what is log4net?
Log4net is a logging framework for the .NET platform. It’s definitely not the only one, but it’s one of the most popular frameworks out there.
A logging framework is a tool that can 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, the formatting of the log message, and any more.
Another very important issue that a logging framework takes care of for you is log targets. By adopting a logging framework, it becomes easy to write your logs to different places 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 it and install it, or just run this quick command from the Package Manager Console:
PM> Install-Package log4net
Add a new file to your project in Visual Studio called log4net.config and be sure to set a property for the file. Set Copy to Output Directory to Copy Always. 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. This will log messages to the console and a log file both. 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 it’s 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 this to the bottom of your AssemblyInfo file.
[assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config")]
Now you can modify your app to log something and try it out!
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 are how you direct where you want your logs sent. The most popular of the standard appenders are most likely the RollingFileAppender and ConsoleAppender.
I would also try the DebugAppender if you want to see your log statements in the Visual Studio Debug window so you don’t have to open a log file.
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 would be viewing the logs and what you want to see later when coding your logging statements.
You can specify in your log4net config which log4net logging levels you want to log.
This is really valuable if you want to specify only certain levels to be logged to a specific log appender or to reduce logging in production. This allows you to log more or less data without changing your code.
log4net levels:
Declaring any variable in your code has overhead. When I have been 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 it 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.
To help resolve these issues, enable internal log4net logging via your web.config file.
<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 Elasticsearch 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, which is designed for this.
They can 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 setup your own elasticsearch cluster for it.
If you want to query all the files on disk, consider using VisualLogParser.
Filters can be configured to suppress specific log messages. Take a look at these examples.
Here’s how you can filter by the text on 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 want to do something that the standard appenders do not support, you can search online for one or write your own.
One example could be an appender for writing to Azure Storage. Once upon a time, we wrote one to send our logs to Azure Table storage to centralize them. We couldn’t really query them due to the lack of full-text indexing, but we could view 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 some other notable fields you can log, although they can have a big performance impact to your app and would not be recommended for high volume logging on a production application.
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");
Additionally, you can assign objects in contexts to use what it calls “active property values.” When the log message is written, the ToString() method will be called which can dynamically do something.
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");
}
If you add %property{activity} to your pattern layout, you can now see a transaction ID in your logs like so.
Your log messages may still look like spaghetti, but at least you can easily see which ones go together.
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");
}
By default, you can log an object to it and it will serialize it with its default renderers.
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 that does it. 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 really 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 going on 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.
To deploy a piece of software to a production environment without any type of logging would be unthinkable nowadays. Doing so would amount to take a walk in a huge city, during rush hour, blindfolded.
Software is a very complex thing.
When you release an application, deploying it to a (potentially) unknown environment, you can’t know for sure that everything is going to work as intended.
If something goes wrong—and it will—logging is one of the few ways you can use to “go back in time,” understand the problem, and fix it.
Today’s post covered the log4net logging framework. You learned what a logging framework is, and how they can relieve the burden you might face as a developer having to come up with a logging strategy.
We also shared a list of best practices and tips you can start employing right away to make your journey with log4net easier.
Thanks for reading, and see you next time.
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 stackify@stackify.com
