A Treatise on Using Debug and Trace classes, including Exception Handling

• Download source files - 2 Kb

Introduction

VS.NET provides two mechanisms to aid the programmer in diagnosing and correcting programming errors. One is the Debug class, and the other is the Trace class. These two classes contain an Assert function. The Assert statement is used to verify value, and in many cases, that the value of, say a pointer, is not null after invoking some system API. With the inclusion of try-catch blocks, it seems that we are migrating to a different approach, one in which the system API throws an exception which we have to “catch”. This makes our lives more complicated because now we cannot simply test the return of an API function for a failure return; we have instead to handle “exceptions”. Finally, life as a programmer is complicated by the fact that we build two kinds of versions of our programs—the debug version and the release version.

This article attempts to discuss these issues from the point of view of one biased programmer, based on his experiences in the real world, working with hardware engineers, junior grade programmers, feisty QA staff, and “touch it and it breaks” marketing people.

Now, if you’re one of those programmers that doesn’t use asserts and traces, then you might as well stop reading here, because nothing I say is going to motivate you to start programming in a way that makes your life easier, lowers the cost of the development cycle, and gives you useful feedback when your product goes in to the test cycle.

An Example Of A Project Development That Worked

Several years ago I was the team leader for a multi-channel video surveillance system, accepting video feeds from up to 64 cameras over four RS-232 lines, connected either directly to the video sources or via a leased line modem or a dial up line. There were various complexities of the project that I’m not going to get into here.

Instrumentation: trace logs

At the very start of the project, we instrumented:

1. all GUI based events—menu selections, button selections, etc.;
2. all internal messages (we used a messaging architecture to isolate functional components);
3. all state changes.

By “instrumented”, I mean that we output to a debug log file informative messages regarding events, messages, and current state. Additionally, we instrumented various “mission critical” variables that fell outside of the event/message/state domain.

Instrumentation: Asserts

We also asserted the correctness for parameter inputs to all functions and asserted the return values of those functions. An assertion was also output to the debug log. When an assert occurred, the debug log was closed, a message was displayed, and the program was terminated.

Uncooperative QA Personnel

During development, the QA department tested various modules as they became functional. Initially, the relationship with the QA department was rather adversarial, and because of our instrumentation, we discovered that QA was testing precisely the functions we told them not to test (they literally wanted us to fail in management’s eyes). After correcting various perceptions, the QA people actually started producing useful work. One of the problems with any tester is that when asked “what did you do”, they will confidently say, I clicked on X, then Y, then Z, when in reality they clicked on A, B, and C. As a result of our instrumentation of all GUI events, we never had to ask what the tester did, we could figure it out from the log.

Field Testing

Because in-house use is different from actual field use, we also provided the program in a “beta” form to select customers with the instrumentation enabled. This revealed some issues, mostly with hardware differences, that we didn’t see in-house.

Regression Testing

Finally, because of the way the instrumentation hooked into the GUI’s, we were able to record and playback test scripts to automate time consuming yet useful test procedures, so we were actually able to do regression testing—the ability to test what used to work on the new code.

Development Testing

Needless to say, the instrumentation was highly useful during our own coding (especially coupled with version control, which allowed us to revert to previous versions and test the same event sequence).

Shipped Ahead Of Schedule

Management, having been burned on previous projects and having irate customers to deal with, allocated 3 months for testing (an unheard of amount of time because the coding took only 6 months, and testing was ongoing during coding also!) After only one month, the QA department was unable to find further bugs and the product shipped ahead of schedule.

Release vs. Debug

For performance reasons, because the application described above was so heavily instrumented, we turned off all trace statements but left in the assert statements in the release mode. This was also done because in the field the program would be running continuously, and the log file would get unmanageably large. Furthermore, the assert statements produced a valuable message as to where and why the assert occurred, because inevitably something will fall through the QA testing process, especially in the world of ever changing hardware.

I believe that this is a good philosophy, to ship an un-instrumented release version to the customer. If the customer is repeatedly having problems and they are willing to work with you, then you can send them a debug version with full trace capability. In addition, with a properly implemented assertion handler, you can display a graceful error message to the user. I love the error message that IE 6 comes up with—something like “we’re sorry to inconvenience you, but a problem has been detected, etc.” It even gives you the option of automatically restarting the application. From a user’s point of view, it’s more like getting bruised by an air bag instead of thrown through the windshield—a definite improvement. If the customer has Internet access, then the application can send you some information about the error, and this is where leaving the asserts in the release code comes in handy—you can get useful information beyond an execution stop address, some stack information, and a register/memory dump.

Debug vs. Trace

In C#, two classes, Debug and Trace, are provided. While both can be disabled, by default both are on in the debug build mode. When in the release build mode, the Debug functions are disabled while the Trace functions remain enabled. Now, both classes support assertions and tracing, however, given the names of these classes, one would more likely use Debug.Assert for assertions and Trace.Write for traces.

If you buy into the logic I discussed regarding asserts and traces, this is exactly the wrong thing to do. Because of performance and application lifetime considerations, the pure trace functions should be removed in the release version, and the Debug.Assert statements should be left in!

Thus, an application should use Debug.Write for traces and Trace.Assert for assertions. When built under release mode, the Debug.Write statements are inactivated but the assertions are left in.

The Trace Switch

C# has the ability to, without recompiling, modify the trace flag. This enables you to turn on tracing at different levels in a release version of your program. I consider this to be of dubious value for two reasons—one, your program still incurs the performance hit of the function call, and second, anyone with minimal programming experience can adjust the trace level and thus learn important information about your program that my reveal corporate secrets or compromises the security of your system. This is another good reason not to use the Trace class for instrumentation logs.

Exception Handling with Try and Catch Blocks

It appears that we have to live with handling errors with try-catch blocks because API’s are now shipping that throw exceptions as the “new and improved” method of reporting errors (instead of, for example, returning a result status or a value to test against indicating failure). This means that we are now left with the dilemma of how to handle the exception. In the old days, we would have handled the error either with an assert or a conditional test, assuming there was some graceful way to back out of the function. So, how do we deal with exceptions from the viewpoint of asserts, traces, debug and release builds?

The programmer has only one decision to make regarding an exception: can it be gracefully handled? For example, can the file read operation be terminated with an informative message to the user without terminating the application? If the answer is “yes”, then code the exception accordingly. If the answer in “no”, then generate an assert. In the cases where some information can be gleaned as to the type of exception, then this becomes valuable information in making addition decisions as to how to handle the exception and what information to display as part of the “this program has failed” message.

A third class of exceptions exists, which I think is much rarer, and this is the kind of exception that doesn’t impact the operation of the program. Perhaps the program is testing for a feature. For example, “is there a CD in the drive”. The programmer may have no choice other than to handle a “no” answer as an exception, with the result that a CD-ROM icon is simply not displayed in a file list.

Introducing “Warn”

Let’s assume that in the discussion above, the exception can be gracefully handled, but it indicates a failure of some kind. So, we still want to inform the user of the failure. This is accomplished with a “Warn” message. Wouldn’t it be nice if a debug class had this capability, so warnings could also be logged in our debug mode, produce a warning message in the release mode, and wouldn’t be fatal to the application?

Introducing The “Possible Problem/Reason Dictionary”

Wouldn’t it also be nice if we could display to the user some information as to the problem, and the possible reasons for this problem? This is accomplished with a problem/resolution dictionary. Each assertion or warning would reference one or more problem/reason statements that would be displayed as part of the “this program must terminate” message. Placing these messages in a dictionary means that you can easily generate this information for the documentation department, perhaps to be included in an appendix or a help system.

Note that both asserts and warnings can reference the same dictionary, making for a flexible feedback system for the user.

Behind The Scenes

I wanted to test what the actual assembly code looks like for both Debug classes, using the Assert and WriteLine methods.

Using the following C# code:

Debug.WriteLine("Debug.WriteLine");
System.Diagnostics.Trace.WriteLine("Test.WriteLine");
            
Debug.Assert(false, "Debug.Assert");
System.Diagnostics.Trace.Assert(true, "Trace.Assert");

In debug mode, the compiler generates the following code:

            Debug.WriteLine("Debug.WriteLine");
0000000f  mov         ecx,dword ptr ds:[01BA03CCh] 
00000015  call        dword ptr ds:[02EF870Ch] 
            System.Diagnostics.Trace.WriteLine("Test.WriteLine");
0000001b  mov         ecx,dword ptr ds:[01BA03D0h] 
00000021  call        dword ptr ds:[02EF89F4h] 
            Debug.Assert(false, "Debug.Assert");
00000027  mov         edx,dword ptr ds:[01BA03D4h] 
0000002d  xor         ecx,ecx 
0000002f  call        dword ptr ds:[02EF86ECh] 
            System.Diagnostics.Trace.Assert(true, "Trace.Assert");
00000035  mov         edx,dword ptr ds:[01BA03D8h] 
0000003b  mov         ecx,1 
00000040  call        dword ptr ds:[02EF89D4h] 

In release mode, the compiler generates:

0000000f  mov         ecx,dword ptr ds:[01BA03CCh] 
00000015  call        dword ptr ds:[02EF870Ch] 
0000001b  mov         edx,dword ptr ds:[01BA03D0h] 
00000021  mov         ecx,1 
00000026  call        dword ptr ds:[02EF86ECh] 

This is interesting:

1. The debug statements are completely removed;
2. The Trace.WriteLine call uses the Debug.WriteLine function;
3. The Trace.Assert call uses the Debug.Assert function.

To summarize: all Debug function calls are removed, and the Trace functions are changed to call the Debug class functions! This is undoubtedly all controlled by the “Conditional” attribute capability of C#, and we will use the same methodology to implement a “smarter” debug class.

Implementing A Custom Debug Class

Unfortunately, the Debug and Trace classes cannot be overridden, so we have to implement our own version. In this class:

1. Trace functions use the conditional “DEBUG” attribute;
2. Assert functions use the conditional “TRACE” attribute;
3. A “Warn” function has been added;
4. An warning/error dictionary has been added;
5. Implements all current functionality of Trace/Debug classes;
6. Easily initialize logging to a text file;
7. Warn and Asserts, using the Dbg type, produce “user friendly” message boxes;
8. Can hook into the unhandled exception handler to further enhance user friendliness.

Listeners And Member Functions

Interestingly, the Debug and Trace classes use the same Listeners. If you add a listener using the Debug.Listeners.Add method, this listener is also active when using the Trace class methods. This is also true of the indent functions and other functions. This also means that a class that mirrors and extends the Debug and Trace class functionality need only pass functions through to one of the two .NET classes.

Debug vs. Release

In the debug class provided in this article, the following differentiation is made:

Debug mode:

includes all Trace mode functionality, plus:
all write functions are enabled
adding a file listener is enabled
all functions having to do with indenting, flushing, and closing listeners are enabled

Trace mode:

An Unhandled exception handler can be initialized (built in to the class)
Warnings can be output (Warn method)
Asserts are enabled

The Unhandled Exception Handler

The following code instantiates an unhandled exception handler. This provides a more graceful way to terminate the application, and in debug mode, outputs the exception to the log file.

[Conditional("TRACE")]
public static void InitializeUnhandledExceptionHandler()
{
    AppDomain.CurrentDomain.UnhandledException += 
             new UnhandledExceptionEventHandler(DbgExceptionHandler);
}

public static void DbgExceptionHandler(object sender, 
                                       UnhandledExceptionEventArgs args)
{
    Exception e=(Exception) args.ExceptionObject;
    Trace.WriteLine("Exception: "+e.Message+"\n"+e.GetType() + 
                    "\nStack Trace:\n"+e.StackTrace);
    MessageBox.Show(
        "A fatal problem has occurred.\n"+e.Message+"\nin: "+e.GetType(),
        "Program Stopped",
        MessageBoxButtons.OK,
        MessageBoxIcon.Stop,
        MessageBoxDefaultButton.Button1);
    Trace.Close();
    Process.GetCurrentProcess().Kill();
}

Notice that the exception handler can be initialized for both Debug and Trace conditions, meaning both Debug and Release modes.

The Warn Method

The following code can be used in exception handlers to output a warning to the user that some corrective action ought to be taken. The Warn method uses the problem dictionary to indicate the problem and look up the reasons associated with the problem. This is presented in a (hopefully) nice way to the user.

[Conditional("TRACE")]
public static void Warn(bool b, DbgKey key)
{
    if (!b)
    {
        Trace.WriteLine("Warning: "+key.Name);
        if (problems.Contains(key))
        {
            string explanation=GetExplanation(key);
            MessageBox.Show(
                explanation,
                "Warning",
                MessageBoxButtons.OK,
                MessageBoxIcon.Warning,
                MessageBoxDefaultButton.Button1);
        }
        else
        {
            MessageBox.Show(
                "A problem has occurred that should be corrected.\n\nReference: "
                +key.Name,
                "Warning",
                MessageBoxButtons.OK,
                MessageBoxIcon.Warning,
                MessageBoxDefaultButton.Button1);
        }
    }
}

The Assert Method

The assert method, when invoked using the overloaded method Assert(bool b, DbgKey key) outputs a trace line containing the assertion and produces a user friendly message. This message, as with the Warn method above, uses the problem dictionary to show some hopefully usefull information to the user.

[Conditional("TRACE")]
public static void Assert(bool b, DbgKey key)
{
    if (!b)
    {
        Trace.WriteLine("Assert: "+key.Name);
        if (problems.Contains(key))
        {
            string explanation=GetExplanation(key);
            MessageBox.Show(
                explanation,
                "Program Stopped",
                MessageBoxButtons.OK,
                MessageBoxIcon.Stop,
                MessageBoxDefaultButton.Button1);
        }
        else
        {
            MessageBox.Show(
                "A fatal problem has occurred.\n\nReference: "+key.Name,
                "Program Stopped",
                MessageBoxButtons.OK,
                MessageBoxIcon.Stop,
                MessageBoxDefaultButton.Button1);
        }
        Trace.Close();
        Process.GetCurrentProcess().Kill();
    }
}

The Verify Method

public static void Verify(bool b)
{
    Assert(b, new DbgKey("_NEVER_FAIL_"));
}

Adding A Log File

To add a log file, invoke the LogOutput method:

[Conditional("DEBUG")]
public static void LogOutput(string fn)
{
    Debug.Listeners.Add(new TextWriterTraceListener(fn));
    DateTime dt=DateTime.Now;
    Debug.WriteLine("Debug Logging Initialized: "+dt.ToString());
}

Usage

The following code shows some typical usage examples:

Dbg.LogOutput("out.txt");
Dbg.InitializeUnhandledExceptionHandler();
Dbg.Problems.Add(new DbgKey("IO"),
    "Cannot create file.",
    new String[] {
        "The specified path is invalid.",
        "The network connection is down.",
        "The file already exists."});
Dbg.Warn(false, new DbgKey("IO"));
Dbg.Warn(false, new DbgKey("Foo"));
Dbg.WriteLine("A trace message");
int a=0;
int n=1/a;      // generate an unhandled exception

// comment out above exception to make this happen
Dbg.Assert(false, new DbgKey("IO"));  

Concluding Remarks

In the above discussion, we have identified that in debug mode, both asserts and traces should be enabled, and in release mode, only asserts should be enabled. Secondly, we have identified that exceptions generated by try-catch blocks that the application cannot handle should assert, whereas those that are handled should possibly generate a warning to the user. Lastly, we have identified that an assertion should provide some problem/resolution information to the user. Also, in the debug version of the program, all trace and asserts are logged, whereas in the release version, there is no logging.

Also, it might be nice to extend this class to read the problem dictionary in from, say, an XML file.

Updates

1. Fixed a serious bug, in which the boolean condition was not being tested in the Warn and Assert functions. How embarassing!
2. As suggested in the responses below, added a Verify method and added the stack trace to the exception handler. Note that the Verify method doesn't exactly correlate to the C++ VERIFY macro. This is due to the limitations of the [Conditional] attribute--you can't perform boolean logic.
3. I added a Fail method that can be used in conjunction with exceptions that are trapped but not recoverable.

References

Writing Custom .NET Trace Listeners, Vagif Abilov (CodeProject)
General Guidelines for C# Class Implementation, Eddie Velasquez (CodeProject)