I think about logging pretty often as I code solutions. To me, logging is an important part of a quality software product. In the middle of the night, when your software goes haywire, being able to explore a well-detailed application log file (not just the event logs or IIS logs, for example) can be critical in remediating the problem and reducing the number of lost hours of sleep.
I think a good logging solution should include:
- The ability to be turned off or on from outside the compiled solution (eg. from the configuration file).
- Persistence ignorance—maybe today I want to log to a flat file, but tomorrow I want to log to a database. I should be able to easily swap persistence providers without recompilation. With regard to flat file logging, I’d like the option to be able to specify a relative path or absolute path for the log file (although, for web apps, that could serve as a security vulnerability). Also, a rolling log file provider is a must.
- The ability to crank up or crank down the verbosity of the logging solution.
- Some control over the look of the log file. Although I might, on occasion, crack open a log file in notepad and manually walk through it, most log files I deal with are quite large—I’d rather use tools like LogParser to produce human-readable reports from the generally-not-human-readable log file. By having some control over the data that’s added to my log files and how that data is delimited, it can be easier for me to write scripts that render powerful reports (some day, I do hope to put up a post on how I’ve used LogParser to produce meaningful reports based on my application logs).
I could also add to the list that the solution must be hidden behind an interface for easy injection via Dependency Injection. The easy winner here, in my opinion, is log4net. If you’re not familiar with log4net, it is a light, open-source API that meets all of these needs and more. Here are my quick notes on implementing the library:
Step 1: Configure it
…in your application configuration file
<configSections>
<section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
</configSections>
<log4net>
<!-- A1 is set to be a ConsoleAppender -->
<appender name="A1" type="log4net.Appender.RollingFileAppender">
<file value="logs\log4net.log"/>
<appendToFile value="true"/>
<datePattern value="yyyyMMdd"/>
<rollingStyle value="Date"/>
<!-- A1 uses PatternLayout -->
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%-4timestamp|%thread|%-5level|%logger|%ndc|%message%newline"/>
</layout>
</appender>
<!-- Set root logger level to DEBUG and its only appender to A1 -->
<root>
<level value="ALL"/>
<appender-ref ref="A1"/>
</root>
</log4net>
…and in your AssemblyInfo.cs file
[assembly: log4net.Config.XmlConfigurator(Watch = true)]
Step 2: Add a reference to log4net.dll
Step 3: Code Away
using System;
using System.Reflection;
using log4net;
namespace WebApplication1
{
public partial class log4net : System.Web.UI.Page
{
private static readonly ILog log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
protected void logButton_Click(object sender, EventArgs e)
{
log.Debug("some Debug msg");
log.Error("some Error msg");
log.Fatal("some Fatal msg");
log.Info("some Info msg");
log.Warn("some Warn msg");
}
}
}
So, log4net’s great for your everyday application needs, but I have a new requirement: most of what I do anymore is write libraries and frameworks for others to use. I want to litter my APIs with lots of log messages so that, should a developer want to know what my API is doing, he should just be able to flip a configuration switch and get a log of the activities of my API. It seems a little presumptuous of me to introduce yet one more dependency on my customer—the log4net dependency—just to be able to use my API. In this situation, I’d prefer to be able to leverage any kind of logging opportunities in the base class library itself. The System.Diagnostics namespace gives me some of this opportunity, but none of the native options are as rich or powerful as log4net.
System.Diagnostics.TraceSource
I find the newer System.Diagnostics.TraceSource not even a viable option for me. TraceSource seems nothing more than the older System.Diagnostics.Trace with less options (eg. no throttling). So, let’s skip TraceSource and talk about Trace.
System.Diagnostics.Trace
It used to be that I would configure a TraceListener like this:
<system.diagnostics>
<switches>
<add name="MagicTraceSwitch" value="Verbose"/>
</switches>
<trace autoflush="true" indentsize="4">
<listeners>
<clear/>
<add name="fileListener"
type="System.Diagnostics.TextWriterTraceListener"
initializeData="logs\SysDiag.log"
traceOutputOptions="DateTime"/>
</listeners>
</trace>
</system.diagnostics>
Then I’d start coding against the namespace as such:
public partial class _Default : System.Web.UI.Page
{
private TraceSwitch MyTraceSwitch = new TraceSwitch("MagicTraceSwitch", "switch from config file");
protected void Button1_Click(object sender, EventArgs e)
{
Trace.WriteLineIf(MyTraceSwitch.TraceInfo, "log some informational message.");
Trace.WriteLineIf(MyTraceSwitch.TraceVerbose, "log some verbose message.");
}
}
Since System.Diagnostics is part of the BCL, no extra dependencies are required and I can ship just my APIs with no other third party assemblies. I have at least two problems with this approach, though: 1) the TextWriterTraceListener has no rolling log file capabilities and 2) the way I’m pushing messages out to the listener, via the Trace.WriteLineIf statement, means that only the exact string message in my argument gets inserted into my log—no nicely delimited line with timestamp, thread id, etc.
To address my second problem, I could use a different set of methods in the Trace class:
Trace.TraceError("an error happened.");
Trace.TraceInformation("this is an information trace {0} {1}", "parm1", "parm2");
Trace.TraceWarning("this is a warning trace {0} {1}", "parm1", "parm2");
Interestingly, though, these methods don’t throttle—they pay no attention to my TraceSwitch setting. All these messages will get logged regardless of the verbosity setting. The log entries will, however, include the values “Error”, “Warning”, and “Information” if that’s any consolation. To format the log entry, the listener configuration includes a “Delimiter” attribute and a traceOutputOptions attribute.
To address the first problem, I’ve recently discovered the Microsoft.VisualBasic.Logging.FileLogTraceListener, thanks to this post on StackOverflow. Here’s a configuration I’ve used for this listener:
<system.diagnostics>
<switches>
<add name="MagicTraceSwitch" value="Warning"/>
</switches>
<trace autoflush="true" indentsize="4">
<listeners>
<clear/>
<!--<add name="fileListener"
type="System.Diagnostics.TextWriterTraceListener"
initializeData="logs\SysDiag.log"
traceOutputOptions="DateTime"/>-->
<add
name="fileListener2"
type="Microsoft.VisualBasic.Logging.FileLogTraceListener, Microsoft.VisualBasic, Version=8.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL"
CustomLocation="C:\data_files\app_development\LoggingTest\WebApplication1\logs"
Location="Custom"
BaseFileName="MyApp"
LogFileCreationSchedule="Daily"
Delimiter="|"
traceOutputOptions="ProcessId, DateTime"/>
</listeners>
</trace>
</system.diagnostics>
One thing to note about this listener is that, unlike the TextWriterTraceListener, the FileLogTraceListener seems to only accept an absolute file path, not a relative one—if you can deal with that, this listener seems to be a viable option—although if I were writing an end-to-end application, not just a framework, I’d definitely go with log4net for my logging solution.