<< Tracing and Debugging - Part 1 | The right tool for the right job... >>

Tracing and Debugging - Part 2

April 23, 2010 12:49 by author

In part 1 we looked at how we can implement tracing and debugging to know what our program is doing and any error it may encounter. In this post we'll take a look at more ways to use the Trace and Debug classes, the listener's output, and implementing an easy way to get plenty of information in our trace files with minimal code.

In these examples we're going to use a lot of boilerplate code. This is only necessary for us to show what kind of information we want our trace files to have. In a later post we'll learn how to remove almost all this boilerplate code and still have all the tracing functionality we need.

The main purpose of this post is to give you ideas on how you can implement tracing in your own applications.

Initial Setup

Let's say we have the following program which is failing and we should add some tracing to it. It uses the Person class which knows the age the person. Adding robust trace functionality to this small program may seem over the top but it becomes invaluable in more realistic (and complex) situations.



using System;

namespace DebugAndTrace
{
    class Program
    {
        static void Main()
        {
            try
            {
                Person john = new Person("John Galt", new DateTime(1971, 1, 1));
                Console.WriteLine("{0} is {1} years old.", john.Name, john.Age);

                Person hank = new Person("Hank Rearden", DateTime.Now.AddYears(1));
                Console.WriteLine("{0} is {1} years old.", hank.Name, hank.Age);
            }
            catch (ArgumentException aEx)
            {
                Console.WriteLine("Invalid arguments. " + aEx.Message);
            }
            catch (Exception ex)
            {
                Console.WriteLine("Unknown exception ocurred. " + ex.Message);
            }

            Console.ReadKey();
        }
    }

    class Person
    {
        public Person(String name, DateTime dateOfBirth)
        {
            Name = name;
            DateOfBirth = dateOfBirth;
        }

        public String Name { get; set; }

        private DateTime dateOfBirth;
        public DateTime DateOfBirth 
        {
            get
            {
                return dateOfBirth;
            }
            set
            {
                if (value > DateTime.Now)
                    throw new ArgumentException("Date of birth cannot be a future date");
                dateOfBirth = value;
            }
        }

        public Int32 Age
        {
            get
            {
                Int32 age = new DateTime(DateTime.Now.Subtract(DateOfBirth).Ticks).Year - 1;
                return age;
            }
        }
    }
}

The console output is going to be:

John Galt is 39 years old.
Invalid arguments. Date of birth cannot be a future date

Adding Basic Tracing

Let's add tracing to this application so we can have a better understanding of what our program was doing when the error occurred.



using System;
using System.Diagnostics;

namespace DebugAndTrace2
{
    class Program
    {
        static void Main()
        {
            StartTrace();

            try
            {
                Trace.WriteLine("Starting program");

                Person john = new Person("John Galt", new DateTime(1971, 1, 1));
                Console.WriteLine("{0} is {1} years old.", john.Name, john.Age);

                Person hank = new Person("Hank Rearden", DateTime.Now.AddYears(1));
                Console.WriteLine("{0} is {1} years old.", hank.Name, hank.Age);

                Trace.WriteLine("Program finished successfully");
            }
            catch (ArgumentException ex)
            {
                Trace.WriteLine(ex.GetType().Name + " - " + ex.Message);
                Console.WriteLine("Invalid arguments. " + ex.Message);
            }
            catch (Exception ex)
            {
                Trace.WriteLine(ex.GetType().Name + " - " + ex.Message);
                Console.WriteLine("Unknown exception ocurred. " + ex.Message);
            }
            finally
            {
                Trace.WriteLine("Ending program");
            }

            Console.ReadKey();
        }

        private static void StartTrace()
        {
            String traceFile = @"c:\TraceLog.txt";

            Trace.Listeners.Add(new TextWriterTraceListener(traceFile));
            Trace.AutoFlush = true;
        }
    }

    class Person
    {
        public Person(String name, DateTime dateOfBirth)
        {
            Trace.WriteLine(
                      "Entering Person.ctor ("
                    + "name = " + name
                    + ", dateOfBirth = " + dateOfBirth.ToShortDateString() + ")");
            Name = name;
            DateOfBirth = dateOfBirth;
            Trace.WriteLine("Leaving Person.ctor");
        }

        public String Name { get; set; }

        private DateTime dateOfBirth;
        public DateTime DateOfBirth
        {
            get
            {
                return dateOfBirth;
            }
            set
            {
                Trace.WriteLine("Set Person.DateOfBirth = " + value.ToString());
                if (value > DateTime.Now)
                    throw new ArgumentException("Date of birth cannot be a future date");
                dateOfBirth = value;
            }
        }

        public Int32 Age
        {
            get
            {
                Trace.WriteLine("Calculating " + Name + "'s age");
                Int32 age = new DateTime(DateTime.Now.Subtract(DateOfBirth).Ticks).Year - 1;
                return age;
            }
        }
    }
}

The console output is still the same but we now have a rich trace file to tell us what happened:

Starting program
Entering Person.ctor (name = John Galt, dateOfBirth = 1/1/1971)
Set Person.DateOfBirth = 1/1/1971 12:00:00 AM
Leaving Person.ctor
Calculating John Galt's age
Entering Person.ctor (name = Hank Rearden, dateOfBirth = 4/25/2011)
Set Person.DateOfBirth = 4/25/2011 6:19:03 PM
ArgumentException - Date of birth cannot be a future date
Ending program

Adding Indentation

The trace output doesn't look too bad but we can do a better job of formatting the text. The Trace and Debug classes have the following built in mechanism for indenting your messages:

Trace.Indent()
Increases the IndentLevel by 1

Trace.Unindent()
Decreases the IndentLevel by 1

Trace.IndentLevel
Gets or sets the current number of indents the Trace class will use for output.

Trace.IndentSize
Gets or sets the number of spaces in an indent.

Let's modify the Person class to take advantage of indentation.



    class Person
    {
        public Person(String name, DateTime dateOfBirth)
        {
            Trace.Indent();
            Trace.WriteLine(
                      "Entering Person.ctor ("
                    + "name = " + name
                    + ", dateOfBirth = " + dateOfBirth.ToShortDateString() + ")");
            Name = name;
            DateOfBirth = dateOfBirth;
            Trace.WriteLine("Leaving Person.ctor");
            Trace.Unindent();
        }

        public String Name { get; set; }

        private DateTime dateOfBirth;
        public DateTime DateOfBirth
        {
            get
            {
                return dateOfBirth;
            }
            set
            {
                Trace.Indent();
                Trace.WriteLine("Set Person.DateOfBirth = " + value.ToString());
                if (value > DateTime.Now)
                    throw new ArgumentException("Date of birth cannot be a future date");
                dateOfBirth = value;
                Trace.Unindent();
            }
        }

        public Int32 Age
        {
            get
            {
                Trace.Indent();
                Trace.WriteLine("Calculating " + Name + "'s age");
                Int32 age = new DateTime(DateTime.Now.Subtract(DateOfBirth).Ticks).Year - 1;
                Trace.Unindent();
                return age;
            }
        }
    }

Once again the console output is still the same but we now have a better trace file to tell us what happened:

Adding More Information

In my trace files I like to see much more information than just the messages. Namely I want to see the date and time of events, the method's name, its depth level, the thread id, and declaring type name. One way to do this is by using a helper class like the following:



    class TraceHelp
    {
        private static String delimiter = "\t";
        private static String Delimiter
        {
            get { return delimiter; }
            set { delimiter = value; }
        }

        public static void WriteLine(String message)
        {
            var callingMethod = new StackFrame(1).GetMethod();

            String output =
                   message
                 + Delimiter
                 + Trace.IndentLevel.ToString()
                 + Delimiter
                 + Thread.CurrentThread.ManagedThreadId.ToString()
                 + Delimiter
                 + DateTime.Now.ToString()
                 + Delimiter
                 + callingMethod.DeclaringType.FullName
                 + Delimiter
                 + callingMethod.Name;

            Trace.WriteLine(output);
        }
    }

Now all we have to do is replace Trace.WriteLine with TraceHelp.WriteLine and we'll get a tab delimited file (by default) which we can open up in Excel: