This is the first in a series of posts to shed some light into tracing and debugging techniques. We'll start with the basics, configurations (via code and settings file), and then move on to more advanced topics like implementing your own customized trace listener and using aspect oriented programming to trace/debug an entire class/assembly by adding an attribute to it.

In this post we'll take a look at simple debugging and tracing techniques in the .NET Framework.

Debugging is the process of exterminating bugs (malfunctions) in your code. To do so developers use the Debug and Trace classes to know what happens in the program. The job of these classes is to simply output the information you give them to one or more receivers.

On one side you have your Debug/Trace class and on another you have listeners waiting to receive the information. The listeners in turn will do whatever they're designed to do with the information (show it on screen, save it to a file or database, send an email, etc.).

The following example will send the message "Starting Application" to any listener which is observing the Debug class (more on listeners later).

The main difference between the Debug and Trace classes is that all Debug calls get stripped from your code when you compile in release mode. The Trace calls do make it to your client after you ship out your code.

In general you should use Debug for any information you don't want your final users to see, when you output sensitive information like user/server names, or information about the inner workings of your application (like stack trace). Trace should be used for everything else (what's happening with your program).

Lets get practical...

Always remember that when you use Debug or Trace you are essentially broadcasting your messages to anyone who's listening. The default listener is System.Diagnostics.DefaultTraceListener and it will display your messages in the Output window in Visual Studio (Ctrl + W, O).

using System;
using System.Diagnostics;

namespace DebugAndTraceExample
{
    class Program
    {
        static void Main()
        {
            Debug.WriteLine("Main block started");

            /* Do some work */

            Debug.WriteLine("Main block ended");

            Console.ReadKey();
        }
    }
}

Notice that we're using the System.Diagnostics namespace which contains the Debug (and Trace) class.

Who's listening?

Since we haven't specified any listener, the message goes to the default listener (the Output window):

Here you can see our debug messages in the end. The rest of the output window contains debug information which Visual Studio automatically sends to the default listener.

The Debug.Listeners property contains the list of objects who are listening for your messages. To verify that there's no magic involved in writing to the Output window lets look at the list of listeners right out of the box:

This will print out:

System.Diagnostics.DefaultTraceListener

You can add as many listeners as you want and they will all receive your messages when you send them. Lets add a console listener to our application and verify that our messages are caught by both the default listener (Output window) and the console listener (which prints the messages to the console screen).

The console will show the following:

The Output window will show:

As you can see the Listeners collection did contain the ConsoleTraceListener when we looped through it. Later on we used the Debug class to send the message "Program ended successfully" to everyone who's listening (in our case the default trace listener and the console trace listener).

You can always remove a listener by calling the Listeners.Remove method. For example, you can remove the default listener:

We're using debug, how come Trace Listeners are paying attention to us?

Although all TraceListeners work with the Debug class, some are geared towards the Trace class because it has explicit methods to say what kind of event it is (TraceError, TraceInformation, TraceWarning). In the end, a listener is just a listener. Some have "Trace" in their names, some do not. Both Debug and Trace classes broadcast to listeners inheriting from the TraceListeners class regardless of their names. What the listener does with the information is not the business of the sender (Debug or Trace).

Listeners you can use

• DefaultTraceListener: Sends your messages to the Output window.
• ConsoleTraceListener: Sends your messages to the console.
• TextWriterTraceListener: Send your messages to a text file or a stream. This listener doesn't flush your messages immediately to the file. Instead it waits until you call the Debug.Flush() method.

For example, the following code will write "The application is working" to the file TraceLog.txt

• XmlWriterTraceListener: Sends your messages to an XML file or a stream. This listener doesn't flush your messages immediately to the file. Instead it waits until you call the Debug.Flush() method. It also adds a lot of information to each message so you probably want to use it only if it's required.

For example, the following code sends a small debug message:

Yet the listener produces the following file:

• DelimitedListTraceListener: Sends your messages to a delimited text file.

Debug: When it receives a message from the Debug class, it will write the message to a file the same way TextWriterTraceListener does (it will even ignore any Delimiter and TraceOutputOptions you may specify).

Trace: To get the most out of this listener you should use the following Trace class methods: TraceError, TraceInformation, TraceWarning. Only then will you get a nice delimited file with all the options you specify in the TraceOutputOptions propery.

• EventLogTraceListener: Sends your messages to the event log. The following program will create an event log source and then use the EventLogTraceListener to capture the debug information.

Putting it all together.

The following example shows how you can use tracing and debugging to help you and your users in detecting problems. The main program just divides two numbers and displays the result. If you think there's too much plumbing it's because there is. In a later post I'll show how you can remove most of the plumbing with configuration files and a spect oriented programming. 

using System;
using System.Diagnostics;
using System.Reflection;

namespace DebugAndTraceExample
{
    class Program
    {
        static void Main()
        {
            String traceFile = @"c:\TraceLog.txt";
            try
            {
                Debug.WriteLine("Starting trace listener");
                using (TextWriterTraceListener listener = new TextWriterTraceListener(traceFile))
                {
                    Trace.Listeners.Add(listener);

                    PerformDivisions();
                }
            }
            catch (Exception ex)
            {
                Debug.WriteLine(ex.Message);
                Console.WriteLine("Could not open the file '{0}' to store our tracing information.");
            }

            Console.WriteLine("");
            Console.WriteLine("Press any key to exit.");
            Console.ReadKey();
        }

        static void PerformDivisions()
        {
            String methodName = MethodBase.GetCurrentMethod().Name;
            try
            {
                Trace.WriteLine("Entering " + methodName);

                Trace.WriteLine("About to divide 10 by 5");
                Double result1 = Quotient(10, 5);
                Trace.WriteLine("Quotient = " + result1.ToString());
                Console.WriteLine("10 / 5 = {0}", result1);

                Trace.WriteLine("About to divide 10 by 0");
                Double result2 = Quotient(10, 0);
                Trace.WriteLine("Quotient = " + result2.ToString());
                Console.WriteLine("10 / 0 = {0}", result2);

                Trace.WriteLine(methodName + " completed without errors");
            }
            catch (DivideByZeroException ex)
            {
                Trace.WriteLine("Exception: " + ex.Message);
                Console.WriteLine("Cannot divide by zero.");
            }
            catch (Exception ex)
            {
                Trace.WriteLine("Exception: " + ex.Message);
                Console.WriteLine("An unknown error ocurred while performing divisions.");
            }
            finally
            {
                Trace.WriteLine("Leaving " + methodName);
            }
        }

        static Double Quotient(Double numerator, Double denominator)
        {
            if (denominator == 0)
                throw new DivideByZeroException();

            return numerator / denominator;
        }
    }
}

This program will output the following:

In this case we're particularly interested in knowing what happened 'behind the scenes'. Here's the Output window:

And here's the trace file created:

In this example we used a trivial division by zero but in the real world a good trace file means the difference between spending hours trying to find the source of the error and finding it in minutes.

Next post is going to be about configuring our trace class and listeners.