Adding Diagnostics to .NET Code

How you can use Framework classes to add diagnostic messages to your code

Richard is the author of Programming with Managed Extensions for Microsoft Visual C++ .NET 2003 (Microsoft Press, 2003). He can be contacted at richard@ richardgrimes.com.

The .NET Framework designers recognized that you'd want to add trace messages liberally in your code. However, since trace messages are only useful for debug builds, the designers had to provide a mechanism so that you would not have to edit your code to remove trace messages from release builds. C# has conditional compilation similar to native C++, where the compiler only compiles a section of code depending on whether a specific symbol is defined (see Listing One). However, this usually results in code that is unreadable. Instead, C# (and VB.NET, but not Managed C++) has support for the [Conditional] attribute, which is applied to methods in libraries and specifies a symbol that must be defined to use the method. Another assembly can have code that calls this method, but the compiler only compiles this call into the final assembly if the symbol is defined.

Contrast Listing Two with Listing One. Listing One uses conditional compilation so that the code only appears in the assembly (app.exe) if the symbol DEBUG has been defined. Listing Two shows fragments of code from two assemblies; all of the code in the first half of the listing is compiled into the first assembly (lib.dll) regardless of whether the DEBUG symbol is defined. The method PrintDebug is added to the assembly and is marked with the [Conditional] attribute. The second fragment of code has a call to this method, but the compiler only adds this to the assembly if the symbol DEBUG is defined. Listing Two is definitely preferable to the code in Listing One; however, note the subtle difference between the two when DEBUG is not defined. In Listing One, the conditional code is not compiled at all; in Listing Two, the conditional code is compiled, but it is not called. The [Conditional] attribute is acted upon by compilers, but the Managed C++ compiler does not recognize this attribute, so you have to use conditional compilation. Listing Three shows how to use macros to access a conditional method.

Trace Messages

Why am I saying this? Well, the Framework library provides two identical classes—Debug and Trace—which are used to provide traces and asserts. These classes only differ in that the methods of Debug are marked with [Conditional("DEBUG")], whereas the methods of Trace are marked with [Conditional("TRACE")]. Visual Studio.NET 2003 C# and VB.NET projects define both DEBUG and TRACE for Debug builds and TRACE for Release builds. Review what I have just said: By default, the methods of Trace can be called in Release builds.

By themselves, the methods of the Trace and Debug classes do very little—they only accept some diagnostic message from your code, and do a little formatting on them. Reporting that message is the work of a trace listener, a class that derives from the abstract class TraceListener. By default, every application domain in a process is initialized with a single trace listener of type DefaultTraceListener. Each application domain will have a collection of trace listeners that you can access through the static Listeners property on either the Trace or Debug class. You can use this collection to add or remove listeners in your code. When an application domain is created, the runtime will read the configuration file for the application and add or remove the listeners mentioned there. Listing Four shows a sample configuration file, which indicates that when an application domain is created, it should not have the default trace listener. Instead, however, it should have an instance of TextWriterTraceListener to log the trace messages to the file mentioned in the initializeData attribute.

What should you trace? There are two main types of data: First, you may want to test code coverage, so it is useful to record each method called and to record the branch of a test statement. The second type of data are metrics of how well your algorithms are working, so you may decide to trace input parameters, results, and selective intermediate values. The problem, of course, is that this represents a large amount of data and the Framework classes provide few tools to help you. To trace a message, you call either the WriteLine or Write method. These methods are overloaded, but in effect, you can trace just a message string, or a message string and a category string. The category string is just a description—it has no effect on how the trace listener handles the trace message.

There are versions of Write and WriteLine that take a Boolean parameter; these are called WriteIf and WriteLineIf. Only if this parameter is True is the method called. Conceivably, you could create a global collection of switches and use this to allow only messages of a specific category to be traced. One suggestion about how to do this is shown in Listing Five—the MySwitches class has public static members so that they can be accessed throughout the assembly. These members indicate if messages of a particular category (in this case, for code that obtains, analyzes, and presents data) should be traced.

The diagnostics namespace contains an abstract class called Switch that can be used to obtain a value from the <switches> element in the application configuration file. There are two classes in the Framework derived from Switch: BooleanSwitch is passed the name of a switch in its constructor, and if the switch value is nonzero, it sets the Enabled property to True; TraceSwitch goes one step further—it returns the value of the switch in the Level Property as one of the values in the TraceLevel enumeration. Listing Six shows how to use the BooleanSwitch. There are two parameters to the BooleanSwitch constructor; the second parameter is not used, it is left over from the first beta of .NET.

Trace Listeners

When you generate a trace message, either through Trace or Debug, the TraceInternal class is called. TraceInternal will access the application domain's Listeners collection and iterate calling an appropriate method on each trace listener. If you call Debug.Write(String), then TraceInternal will call TraceListener.Write(String) on each TraceListener in the collection. If you call the conditional methods (WriteIf or WriteLineIf), then it is the TraceInternal equivalent of these methods that performs the test on the Boolean parameter.

If you call one of the overloads that take a category string, then the trace listener decides what the category parameter means and how to react to it. The implementation of these methods in the base class, TraceListener, merely concatenates the two strings separated by a colon. These methods are virtual, so it is possible that a trace listener could behave differently for each category (for example, it could log only specific categories); however, all of the Framework trace listener classes use the base class implementation.

Asserts

As the name suggests, an assert tests that some condition is True, and if the test fails, the user is informed. Asserts should be used on important conditions where a failure will mean that the code will fault. The default trace listener class recognizes this and indicates that an assert has failed with a modal dialog that you cannot ignore. It is important that you do not let asserts be active in release builds. An assert tells your users that not only is there a bug in your code, but that you thought that there was one and you have released the code without fixing it! Quite rightly, the Debug class has an Assert method, because the only situation when you should use an assert is in a debug build. Again, however, Trace has the same methods as Debug, but you must not be tempted to call Assert on this class. The reason is that by default, C# and VB.NET projects in Visual Studio .NET define the TRACE symbol in release builds, which enables you to call Assert in release builds.

There are three overloads of the Assert method: The most flexible has the condition to check a short message and a long message; the other two have just the short message or no message at all. If you don't provide a message when you receive a failed assert at runtime, you will have no idea about the failure condition. The Fail method does not take a conditional parameter, but can take either a short message or a short and a long message. Clearly you have to perform some logic to determine whether Fail should be called. However, it is useful during development to put a call to Fail in code that has not been completely implemented; for example, when you add an interface to a class, it is good practice to put a call to Fail in each method body. Fail is marked with [Conditional], and like Assert, you should only call it through the Debug class.

All the overloads of Assert and Fail call an overload of TraceInternals.Fail that takes two string parameters; this method iterates through the trace listeners collection calling the Fail(string, string) method on each one. The base class implementation of this method merely appends the long message and the short message to a failure message, and passes this to the trace listener's WriteLine method. This is used by all of the trace listeners except the DefaultTraceListener class. The DefaultTraceListener class displays the assert using a modal dialog, so it is important that you do not let this be shown in code that runs in a service or on a remote server machine. A modal dialog blocks the current thread until the dialog is dismissed and, thus, it must only be used in a situation when there is a human who can dismiss the dialog. Again, the best guard against this is to only call Assert (or Fail) on Debug so that it can only be called in debug builds when, presumably, you have also marked the service to interact with the desktop.

The code handling Assert (and Fail) has more problems. In Figure 1, an assert dialog, the short message, and the long message are displayed on separate lines, which are followed by a stack trace. If the project was compiled with debug symbols (which will be the case for a debug build) and the symbols are available, then the stack trace gives the name of the file and the line number where the method is defined. If the symbols are not available, then the stack trace will not have filename and line number information.

There are some more points to be made about the dialog shown in Figure 1. The names of the buttons are Abort, Retry, and Ignore. The dialog caption gives a helpful hint that Abort means you should quit the application, Retry means that the debugger should attach to the process, and Ignore means the application should continue executing. Why didn't the .NET team use the names Quit, Debug, and Continue on the buttons? The reason is that the dialog is a standard Windows dialog shown by the Win32 MessageBox function, and this function does not let you give custom names to the buttons. Another option would be to use Windows Forms to create a dialog; however, this would mean that every application that uses the diagnostic classes would have a dependency on the system.windows.forms assembly.

If you click Abort, then it just means that the application ends and the assert will not be reported to other trace listeners (which is what you need, because you will want to know exactly what has happened). The only way around this issue is to use either the configuration file, or to programmatically remove the DefaultTraceListener that the system has added to the Listeners collection (called Default) and add it to the end of the collection.

If you call Debug.Assert in Managed C++, you discover that no stack trace is shown. The reason is that the stack trace has the name of each method in the stack, and to do this, the DefaultTraceListener attempts to get the method name and the type of the class. However, in Managed C++, the entry point will be a global method. This means that the type will be null and the code does not check for this—it merely bails out giving an empty string for the entire stack trace. If you add asserts to a process assembly in Managed C++, it is prudent to include the method name and class in the long description. The alternative is to write your own trace listener that fixes this problem.

Default Trace Listener

The Framework library has three trace listeners; see Table 1. DefaultTraceListener sends trace messages to OutputDebugString, Debugger.Log, and a file. OutputDebugString works by throwing the system exception (SEH) 0x40010006, passing the length of the string and the string as exception parameters. Listing Seven shows this: The call to OutputDebugString and RaiseException do the same thing. Windows catches this exception and makes this data available through the shared memory-mapped file DBWIN_BUFFER. Because this buffer is shared, it must be protected from multithreaded access; in particular, only one thread must be able to write to the memory-mapped file at any one time. To do this, the system creates two events—you can find out how these are used by looking at the dbmon example in the Platform SDK. The problem is that OutputDebugString blocks until the process reading the memory-mapped file has set one of these events to indicate it has read the data. In other words, OutputDebugString couples your process to another process that will read the debug string. This is bad news, so you should not generate OutputDebugString messages in release code. Again, this means that you should only generate trace messages through the Debug class in debug builds

DefaultTraceListener will also log a trace message to the Debugger.Log class, which communicates with an attached debugger. If the Visual Studio .NET debugger is attached to a process that generates a trace message handled by DefaultTraceListener, you will see the message appear in the Output window. In addition, you can specify that the message should be appended to a file. To do this, all you have to do is set the LogFileName property to the name of the file, which you can only do programmatically. When a trace message is generated, DefaultTraceListener opens your logging file, writes the message, and then closes the file; no synchronization is used. So if you have two threads generating trace messages, there is a small chance that one thread will have the file open while the other thread attempts to open the file; this will result in a file access fault and a .NET exception. This is tolerable during testing because you know what is causing the issue, but this should not happen in release mode.

Again, the Fail method, shows a modal dialog. In release builds, you should never show an assert dialog, so you should never let Assert or Fail be called in release builds. Even in debug builds you should not allow a modal dialog to be shown in a service. You can prevent this by setting the AssertUiEnabled property to False, which can be done either programmatically or through the configuration file.

Event Log Trace Listener

EventLogTraceListener derives from TraceListener, but overrides very little. There are three constructors, and the one that is called through the configuration file takes a single string, which is the name of the event log source. This means that all messages are sent to the Application log, with the potential detrimental effect of swamping the log with trivial messages so that you cannot see events generated by other processes. The other constructors let you programmatically specify the log and source.

Once the event log is open, it remains open until the trace listener is disposed, or when it is explicitly closed by calling Close. Both trace messages and asserts are handled by writing an event log entry. However, no attempt is made to specify the event log entry type (for example, an assert should be an Error type). The implementation of the EventLog class in Version 1.1 of the .NET Framework is broken because it does not let you log an event using an event log message file, which means that localization is the responsibility of the code generating the event rather than the code displaying the event (which will know what language you would prefer to use to read the messages). All other processes on Windows generate events that are localized by the event log viewer; since .NET deems that it should be different to all other processes, I regard it as a broken implementation. For all of these reasons, I advise you to not use EventLogTraceListener (or even the EventLog class) in release builds, and preferably not to use it at all.

TextWriter Trace Listener

The TextWriterTraceListener class lets you attach any stream to the trace listener. There are several overloaded constructors, and essentially, these let you create the trace listener from an open TextWriter object or an open stream, or you can pass the name of a file and the constructor attempts to open that file (this is the constructor that is called if you specify this trace listener in the configuration file). The trace listener's TextWriter will remain open until the trace listener is disposed or is closed explicitly by calling Close. However, this is a problem if you use the configuration file because every application domain attempts to create the trace listeners identified.

For example, Listing Eight shows the configuration file that specifies that the process should log to a file called "logFile.log." The first application domain to be created creates an instance of TextWriterTraceListener, opens this file for exclusive access, and keeps it open. The second application domain creates another instance of TextWriterTraceListener and attempts to open the same file—this call fails. Listing Nine shows a version of TextWriterTraceListener that is safe to use in processes that have multiple application domains and Listing Ten shows the appropriate configuration file.

If you use this trace listener, it is important that you are aware of Flush. Some streams are buffered and so the data is not written out until the Flush method is called. This method is implemented on TraceListener as well as Debug and Trace. If you call code that is likely to throw an exception, it is important to call Flush before you call this code, or at least call Flush in your exception handler. Asserts are a problem because a failed assert will not throw an exception. In this case, you should set the AutoFlush property of Debug to True or use the autoflush attribute of the <trace> element in the configuration file.

Wrap Up

Postmortem diagnostics are extremely important to determine why your code has failed, so traces and asserts are very important in debug builds. However, there are numerous issues with the Framework diagnostic classes, and for all of these reasons, you should not let diagnostic messages be generated in release builds. Never call Assert in release builds, avoid using EventLogTraceListener in release or debug builds (because it abuses the event log), and if you want to use TextWriterTraceListener, use the class in Listing Nine to prevent issues in processes that have more than one application domain.

DDJ

Listing One

   // Assembly app.exe
   int i = 42;
#if DEBUG
   Console.WriteLine(
      "initial value of i is " + i.ToString());
#endif // DEBUG

// Assembly lib.dll
class DbgCode
{
   [Conditional("DEBUG")]
   public static void PrintDebug(string str)
   {
      Console.WriteLine();
   }
}
// Assembly uselib.exe
int i = 42;
// Next line will compile only if this assembly is compiled with DEBUG defined
DbgCode.PrintDebug("initial value of i is " + i.ToString());

// Call PRINTDEBUG rather than PrintDebug
#ifdef DEBUG
   #define PRINTDEBUG DbgCode::PrintDebug
#else
   #define PRINTDEBUG __noop
#endif

<configuration>
 <system.diagnostics>
  <trace autoflush="true">
   <listeners>
    <remove name="Default"/>
    <add name="myListener" 
     type="System.Diagnostics.TextWriterTraceListener" 
     initializeData="MyListener.txt"/>
   </listeners>
  </trace>            
 </system.diagnostics>
</configuration>

class MySwitches
{
   public static bool DataAcquisition {get;}
   public static bool DataAnalysis {get;}
   public static bool Presentation {get;}
   // Implementation omitted
}
// Use switches
WriteLineIf(MySwitches.DataAnalysis, "Searching for user...");

<configuration>
   <system.diagnostics>
      <switches>
         <add name="DataAnalysis" value="1"/>
      </switches>
   </system.diagnostics>
</configuration>
// MySwitches constructor
static MySwitches()
{
   BooleanSwitch data = new BooleanSwitch(
    "DataAnalysis", "this parameter is not used");
   dataAnalysis = data.Enabled;
   // other code
}

// Unmanaged C++
LPCSTR str = "Test String\n";
OutputDebugString(str);
LPCSTR args[2] = {reinterpret_cast<LPCSTR>(strlen(str)), str};
RaiseException(0x40010006, 0, 2, reinterpret_cast<const DWORD*>(args));

<configuration>
 <system.diagnostics>
  <trace autoflush="true">
   <listeners>
    <add name="myListener"
     type="System.Diagnostics.TextWriterTraceListener" 
     initializeData="logFile.log"/>
   </listeners>
  </trace>            
 </system.diagnostics>
</configuration>

// Defined in assembly domainsafe.dll
class DomainSafeTextTrace : TextWriterTraceListener
{
   public DomainSafeTextTrace() 
   {
      Initialize("Trace");
   }
   // The parameter is the base name for the log file.
   public DomainSafeTextTrace(string str) 
   {
      Initialize(str);
   }
   // Create a file with a name that includes the name of application domain.
   //  This will be unique for each application domain.
   protected void Initialize(string str)
   {
      this.Name = "DomainSafeTextTrace";
      string strFile = str + AppDomain.CurrentDomain.FriendlyName + ".log";
      this.Writer = new StreamWriter(strFile, true);
   }
}

<configuration>
 <system.diagnostics>
  <trace autoflush="true">
   <listeners>
    <add name="myListener"
      type="DomainSafeTextTrace, domainsafe" 
      initializeData="domainSafeLog"/>
   </listeners>
  </trace>            
 </system.diagnostics>
</configuration>