Logging best practices

Question

I'd like to get stories on how people are handling tracing and logging in real applications. Here are some questions that might help to explain your answer.

Frameworks

What frameworks do you use?

• log4net
• System.Diagnostics.Trace
• System.Diagnostics.TraceSource
• Logging application block
• Other?

If you use tracing, do you make use of Trace.Correlation.StartLogicalOperation?

Do you write this code manually, or do you use some form of aspect oriented programming to do it? Care to share a code snippet?

Do you provide any form of granularity over trace sources? E.g., WPF TraceSources allow you to configure them at various levels:

• System.Windows - settings for all of WPF
• System.Windows.Animation - override specifically for Animation.

Listeners

What log outputs do you use?

• Text files
• XML files
• Event log
• Other?

If using files, do you use rolling logs or just a single file? How do you make the logs available for people to consume?

Viewing

What tools to you use for viewing the logs?

• Notepad
• Tail
• Event viewer
• Systems Center Operations Manager/Microsoft Operations Manger
• WCF Service Trace Viewer
• Other?

If you are building an ASP.NET solution, do you also use ASP.NET Health Monitoring? Do you include trace output in the health monitor events? What about Trace.axd?

What about custom performance counters?

Answer 1

I'm not qualified to comment on logging for .Net, since my bread and butter is Java, but we've had a migration in our logging over the last 8 years you may find a useful analogy to your question.

We started with a Singleton logger that was used by every thread within the JVM, and set the logging level for the entire process. This resulted in huge logs if we had to debug even a very specific part of the system, so lesson number one is to segment your logging.

Our current incarnation of the logger allows multiple instances with one defined as the default. We can instantiate any number of child loggers that have different logging levels, but the most useful facet of this architecture is the ability to create loggers for individual packages and classes by simply changing the logging properties. Lesson number two is to create a flexible system that allows overriding its behavior without changing code.

We are using the Apache commons-logging library wrapped around Log4J.

Hope this helps!

* Edit *

After reading Jeffrey Hantin's post below, I realized that I should have noted what our internal logging wrapper has actually become. It's now essentially a factory and is strictly used to get a working logger using the correct properties file (which for legacy reasons hasn't been moved to the default position). Since you can specify the logging configuration file on command line now, I suspect it will become even leaner and if you're starting a new application, I'd definitely agree with his statement that you shouldn't even bother wrapping the logger.

Answer 2

We use Log4Net at work as the logging provider, with a singleton wrapper for the log instance (although the singleton is under review, questioning whether they are a good idea or not).

We chose it for the following reasons:

• Simple configuration/ reconfiguration on various environments
• Good number of pre-built appenders
• One of the CMS's we use already had it built in
• Nice number of log levels and configurations around them

I should mention, this is speaking from an ASP.NET development point of view

I can see some merits in using the Trace that is in the .NET framework but I'm not entirely sold on it, mainly because the components I work with don't really do any Trace calls. The only thing that I frequently use that does is System.Net.Mail from what I can tell.

So we have a library which wraps log4net and within our code we just need stuff like this:

Logger.Instance.Warn("Something to warn about");
Logger.Instance.Fatal("Something went bad!", new Exception());

try {
  var i = int.Parse("Hello World");
} catch(FormatException, ex) {
  Logger.Instance.Error(ex);
}

Within the methods we do a check to see if the logging level is enabled, so you don't have redundant calls to the log4net API (so if Debug isn't enabled, the debug statements are ignored), but when I get some time I'll be updating it to expose those so that you can do the checks yourself. This will prevent evaluations being undertaken when they shouldn't, eg:

Logger.Instance.Debug(string.Format("Something to debug at {0}", DateTime.Now);

This will become:

if(Logger.DebugEnabled) Logger.Instance.Debug(string.Format("Something to debug at {0}", DateTime.Now);

(Save a bit of execusion time)

By default we log at two locations:

1. File system of the website (in a non-served file extension)
2. Email sending for Error & Fatal

Files are done as rolling of each day or 10mb (IIRC). We don't use the EventLog as it can require higher security than we often want to give a site.

I find Notepad works just fine for reading logs.

Answer 3

We use log4net on our web applications.

It's ability to customize logging at run-time by changing the XML configuration file is very handy when an application is malfunctioning at run-time and you need to see more information.

It also allows you to target specific classes or attributes to log under. This is very handy when you have an idea where the error is occurring. A classic example is NHibernate where you want to see just the SQL going to the database.

Edit:

We write all events to a database and the Trace system. The event log we use for errors or exceptions. We log most events to a database so that we can create custom reports and let the users view the log if they want to right from the application.

Answer 4

I have to join the chorus recommending log4net, in my case coming from a platform flexibility (desktop .Net/Compact Framework, 32/64-bit) point of view.

However, wrapping it in a private-label API is a major anti-pattern. log4net.ILogger is the .Net counterpart of the Commons Logging wrapper API already, so coupling is already minimized for you, and since it is also an Apache library, that's usually not even a concern because you're not giving up any control: fork it if you must.

Most house wrapper libraries I've seen also commit one or more of a litany of faults:

1. Using a global singleton logger (or equivalently a static entry point) which loses the fine resolution of the recommended logger-per-class pattern for no other selectivity gain.
2. Failing to expose the optional Exception argument, leading to multiple problems:
   • It makes an exception logging policy even more difficult to maintain, so nothing is done consistently with exceptions.
   • Even with a consistent policy, formatting the exception away into a string loses data prematurely. I've written a custom ILayout decorator that performs detailed drill-down on an exception to determine the chain of events.
3. Failing to expose the IsLevelEnabled properties, which discards the ability to skip formatting code when areas or levels of logging are turned off.

Answer 5

What frameworks do you use?

We use a mix of the logging application block, and a custom logging helper that works around the .Net framework bits. The LAB is configured to output fairly extensive log files included seperate general trace files for service method entry/exit and specific error files for unexpected issues. The configuration includes date/time, thread, pId etc. for debug assistance as well as the full exception detail and stack (in the case of an unexpected exception).

The custom logging helper makes use of the Trace.Correlation and is particularly handy in the context of logging in WF. For example we have a state machine that invokes a series of sequential workflows. At each of these invoke activities we log the start (using StartLogicalOperation) and then at the end we stop the logical operation with a gereric return event handler.

This has proven useful a few times when attempting to debug failures in complex business sequences as it allows us to determine things like If/Else branch decisions etc. more quickly based on the activity execution sequence.

What log outputs do you use?

We use text files and XML files. Text files are configured through the app block but we've got XML outputs as well from our WF service. This enables us to capture the runtime events (persistence etc.) as well as generic business type exceptions. The text files are rolling logs that are rolled by day and size (I believe total size of 1MB is a rollover point).

What tools to you use for viewing the logs?

We are using Notepad and WCF Service Trace Viewer depending on which output group we're looking at. The WCF Service Trace Viewer is really really handy if you've got your output setup correctly and can make reading the output much simpler. That said, if I know roughly where the error is anyway - just reading a well annotated text file is good as well.

The logs are sent to a single directory which is then split into sub-dirs based on the source service. The root dir is exposed via a website which has it's access controlled by a support user group. This allows us to take a look at production logs without having to put in requests and go through lengthy red tape processes for production data.

Answer 6

As the authors of the tool, we of course use SmartInspect for logging and tracing .NET applications. We usually use the named pipe protocol for live logging and (encrypted) binary log files for end-user logs. We use the SmartInspect Console as the viewer and monitoring tool.

There are actually quite a few logging frameworks and tools for .NET out there. There's an overview and comparison of the different tools on DotNetLogging.com.

Answer 7

As far as aspect oriented logging is concerned I was recommended PostSharp on another SO question -

http://stackoverflow.com/questions/3633249/aspect-oriented-logging-with-unity-t4-anything-else

The link provided in the answer is worth visiting if you are evaluating logging frameworks.