Best practices for logging and tracing in .NET

Question

I've been reading a lot about tracing and logging, trying to find some golden rule for best practices in the matter, but there isn't any. People say that good programmers produce good tracing, but put it that way and it has to come from experience.

I've also read similar questions in here and through the internet and they are not really the same thing I am asking or do not have a satisfying answer, maybe because the questions lack some detail.

So, folks say that tracing should sort of replicate the experience of debugging the application in cases where you can't attach a debugger. It should provide enough context so that you can see which path is taken at each control point in the application.

Going deeper, you can even distinguish between tracing and event logging, in that "event logging is different from tracing in that it captures major states rather than detailed flow of control".

Now, say I want to do my tracing and logging using only the standard .NET classes, those in the System.Diagnostics namespace. I figured that the TraceSource class is better for the job than the static Trace class, because I want to differentiate among the trace levels and using the TraceSource class I can pass in a parameter informing the event type, while using the Trace class I must use Trace.WriteLineIf and then verify things like SourceSwitch.TraceInformation and SourceSwitch.TraceErrors, and it doesn't even have properties like TraceVerbose or TraceStart.

With all that in mind, would you consider a good practice to do as follows:

• Trace a "Start" event when begining a method, which should represent a single logical operation or a pipeline, along with a string representation of the parameter values passed in to the method.
• Trace an "Information" event when inserting an item into the database.
• Trace an "Information" event when taking one path or another in an important if/else statement.
• Trace a "Critical" or "Error" in a catch block depending on whether it is a recoverable error.
• Trace a "Stop" event when finishing the execution of the method.

And also, please clarify when best to trace Verbose and Warning event types. If you have examples of code with nice trace/logging and are willing to share, that would be excelent.

Note: I've found some good information here, but still not what I am looking for: http://msdn.microsoft.com/en-us/magazine/ff714589.aspx

Answer 1

The importance of trace types must be chosen not because of where the trace is in code, but because the traced message is more or less important. Example:

Trace a "Start" event when beginning a method, which should represent a single logical operation or a pipeline, along with a string representation of the parameter values passed in to the method.

Use start type when you start a logical operation. This doesn't mean that the start trace must be at the beginning of a method, nor does it mean that a method must have a start trace.

This being said, in most cases, a logical operation will actually start at the beginning of the method. Otherwise, you should ask yourself if the code is refactored correctly.

Tracing parameters may also be a bad idea. You have to think what to trace, case by case. For example it is really bad to trace parameters of a method void Authenticate(string userName, string plainPassword).

Trace an "Information" event when inserting an item into the database.

It depends. Some items must be traced, but not every item.

• For example imagine you are actually inserting a log item into your database. Would you trace logs? And then log traces? And then trace the logging of the trace?
• Another example: you're inserting a sensitive data. This requires auditing. Since you audited the insertion, why tracing it?

Trace an "Information" event when taking one path or another in an important if/else statement.

Again, it depends.

Trace a "Critical" or "Error" in a catch block depending on weather this is a recoverable error.

The action taken after a non-recoverable error can be more than tracing. For example server-side, you would like to store the exception in the database for further analysis. Also, some exceptions are less important than others, and does not require tracing.

Trace a "Stop" event when finishing the execution of the method.

See the first point.

please clarify when best to trace Verbose and Warning event types.

Verbose:

Verbose is used to trace what you need to trace when something goes really wrong. It means that in most cases, you will disable the tracing of verbose messages, but sometimes, you have to debug some parts of your code to understand why something fails on an edge case.

You usually have lots of verbose messages which let you understand really well the application flow. It also means that those messages must be disabled most of the time because:

• otherwise, the log will grow really fast,
• you don't need them most of the time,
• they may contain sensitive data about the application flow.

Think about verbose as a tool you have to use when you don't have an access to the debugger.

Warning:

Warning type trace is used when something wrong and important happens, but is not too crucial to be treated as an error. For example low RAM may emit a warning, but there is no reason to trace an error, since your application can continue, even if it will be slower than usual.

Examples:

• Example 1: the application failed to open the file the user requested to open. The file exists and is not in use, permissions are set correctly, but something blocks the opening of a file. In this case, you will trace an error, since your application cannot manage this case and continue to work as expected by the user (i.e. actually read the file).

• Example 2: after inspection of the error in the first example, you find that the error is caused by the fact that the file path is longer than 259 characters. So you refactor your code to catch PathTooLongException. When, the next time, the user tries to open the same file, the new version of the application shows a message explaining that the file is too long and must be moved to another folder to shorten the full path in order to open this file in this application. You also trace a message.

• Example 3: your application spent twenty seconds opening and parsing a small file while most files take ten to one hundred milliseconds to open and parse. You trace a warning with relevant info: the type of disk where the file actually is, the file system, the size of the file, the exact time spent, the time the computer was on, etc. When the user complains that it takes twenty seconds to open the file, you take the trace to find what happens. You find for example that it takes so long to load the files from a network share when the computer have just started. You explain to the user that the delay is due to the network and is not related to your application.

• Example 4: the opened file is displayed incorrectly. You enable verbose trace where you actually see how the data is loaded from file and then parsed, step by step.

Answer 2

 > say I want to do my tracing and logging using only the standard .NET classes

System.Diagnostics is great because you can configure where which trace-information should go where (file, eventlog, database, ....)

Unfortunately, if you want to use System.Diagnostics you must know in advance (at designtime), which trace-streams should be possible to follow. (In the example article these are Transfer, Resume, Suspend, ...) . These can be configured to be Disabled, Debuglevel or Errorlevel.

I prefer to have a logging system where I can decide at runtime on classlevel/namespacelevel, how detailed the logging should be. For example, all Debug and above from MyNamespace.Business.* but not MyNamespace.Business.Calculations.

If you are using log4net (or Common.logging) every class gets its own logger so you can easily decide which classes get logged at which level.

Since Database operations are in a separate class, there is no more need for a distinct rule

Trace an "Information" event when inserting an item into the database.

Instead I prefer to have these guidelines:

• Tracelevel should show the basic workflow
• Debuglevel should show detailed data and processing within the workflow, including decisions in programflow with reasons (Creating new item because item did not exist in DB)
• Infolevel for starting/stopping services and one entry for every workflow/GUI action started

Answer 3

You can try out the Story framework, it has a unique approach to logging as it "makes" you write all logs (and add other relevant information) in context so when you need to read it later you get everything you need.

It will automatically add the "start" and "stop" concepts as the beginning and end of a story.

And with a rule-based system you can control what to do with each story (context) based on the information it has, for example print all stories that have an error or come from the "admin" user.

Also more information on this blog post