Framework Patterns: Exception Handling, Logging, and Tracing

This chapter is from the book

.NET Patterns: Architecture, Design, and Process

Learn More Buy

This chapter is from the book

This chapter is from the book 

.NET Patterns: Architecture, Design, and Process

Learn More Buy

Recording an error message does not necessarily have to be fast. I am not saying you should ignore sound design practices and provide a sloppy means of error logging. What I am saying is that your exception handling should concentrate on providing the best options for recording errors and not necessarily the fastest means of handling them. When an application fails and it begins to throw exceptions, its performance takes a back seat to that of dealing with the error itself. This is not always the case, because there are systems that require fast failing. However, the majority of the systems I have built required that the framework allow the best means of solving the problem. The first and best option for solving the problem is discovering what the problem is. Unless you are the user of the application, this may not be possible without a log and/or tracing mechanism.

Logging allows anyone to read the state of the system at any time. One of the best places to log is in the exception class itself because the exception has the necessary information to record. Logging can be done in one shot, usually in the final catch block of what could be multiple levels of exception handlers. Another option is to log in real time. Real-time logging is the recording of information while the system is running. This is also referred to as tracing. This helps eliminate the more difficult runtime problems that may occur and that one-time logging may not help to solve. The trick is to capture as much information as possible in the one-time log event so that tracing isn't always necessary in production. Why? Aside from slowing down performance (which you can minimize, as we will see), tracing forces the developer periodically to add tracing function throughout the code, thus cluttering it up. Before we go into how you can architect a robust and flexible tracing system, let's first show how we can build one-time logging into our exception handling.

You saw in the FtpException example how the user had the option of logging by passing in true as the last parameter (bLog). However, all of this functionality was passed onto the base class. Because logging usually conforms to a universal standard in your architecture, this can be implemented in your base exception handling class, as shown below:

Listing 2.3 The beginning of a real base exception class.

public class BaseException : System.ApplicationException
{

   private int m_nCode;

   public BaseException(){;}

   public BaseException(string sMessage, bool bLog) : this(sMessage,
         null, bLog){;}

   public BaseException(string sMessage, System.Exception
         oInnerException, bool bLog) : this(null, 0, sMessage,
         oInnerException, bLog){;}

   public BaseException(object oSource, int nCode, string sMessage,
         bool bLog) : this(oSource, nCode, sMessage, null,          bLog){;}

   public BaseException(object oSource, int nCode, string sMessage,
         System.Exception oInnerException, bool bLog) :
         base(sMessage, oInnerException)
   {
         if (oSource != null)
                     base.Source = oSource.ToString();
         Code = nCode;

         // need to add logic to check what log destination we
         // should logging to e.g. file, eventlog, database, remote
         // debugger
         if (bLog)
         {
               // trace listeners should already initialized, this
               // is called to be prudent
              Utilities.InitTraceListeners();

              // log it
              Dump(Format(oSource, nCode, sMessage,
                                      oInnerException));
         }
   }

   /// <summary>
   /// Writes the entire message to all trace listeners including
   /// the event log
   /// </summary>
   /// <param name="oSource"></param>
   /// <param name="nCode"></param>
   /// <param name="sMessage"></param>
   /// <param name="oInnerException"></param>
   private void Dump(string sMessage)
   {
         // write to all trace listeners
         Trace.WriteLineIf(Config.TraceLevel.TraceError, sMessage);

         // see Utilities.InitTraceListeners()
         // record it to the event log if error tracing is on
         // The EventLog trace listener wasn't added to the
         // collection to prevent further traces
         // from being sent to the event log to avoid filling up the
         // eventlog
         if (Config.TraceLevel.TraceError)
               EventLog.WriteEntry("PMException", sMessage);
   }

   public static string Format(object oSource, int nCode, string
                     sMessage, System.Exception oInnerException)
   {
         StringBuilder sNewMessage = new StringBuilder();
         string sErrorStack = null;

         // get the error stack, if InnerException is null,
         // sErrorStack will be "exception was not chained" and
         // should never be null
         sErrorStack = BuildErrorStack(oInnerException);

         // we want immediate gradification
         Trace.AutoFlush = true;

         sNewMessage.Append("Exception Summary \n")
                    .Append("-------------------------------\n")
              .Append(DateTime.Now.ToShortDateString())
                    .Append(":")
              .Append(DateTime.Now.ToShortTimeString())
                    .Append(" - ")
                    .Append(sMessage)
                    .Append("\n\n")
                    .Append(sErrorStack);

         return sNewMessage.ToString();
   }

   /// <summary>
   /// Takes a first nested exception object and builds a error
   /// stack from its chained contents
   /// </summary>
   /// <param name="oChainedException"></param>
   /// <returns></returns>
   private static string BuildErrorStack(System.Exception
oChainedException)
   {
         string sErrorStack = null;
         StringBuilder sbErrorStack = new StringBuilder();
         int nErrStackNum = 1;
         System.Exception oInnerException = null;

         if (oChainedException != null)
         {
               sbErrorStack.Append("Error Stack \n")
                           .Append("------------------------\n");

               oInnerException = oChainedException;
               while (oInnerException != null)
               {
                     sbErrorStack.Append(nErrStackNum)
                                 .Append(") ")
                      .Append(oInnerException.Message)
                                 .Append("\n");

                     oInnerException =
                           oInnerException.InnerException;

                     nErrStackNum++;
               }

               sbErrorStack.Append("\n----------------------\n")
                           .Append("Call Stack\n")
                 .Append(oChainedException.StackTrace);

               sErrorStack = sbErrorStack.ToString();
          }
          else
          {
               sErrorStack = "exception was not chained";
          }

          return sErrorStack;
   }

   public int Code
   {
         get {return m_nCode;}
         set {m_nCode = value;}
   }

The logging logic in Listing 2.3 is simple. When throwing an exception, the developer has the option of logging by passing in true for the log flag, as shown in this FTP client code snippet:

Listing 2.4 Applying our base exception child class.

FtpWebResponse = FtpWebResponse.Create(ControlStreamReader);
switch(FtpWebResponse.Code)
{
   case Constants.POSITIVE_COMPLETION_REPLY_CODE:
   {
         // success  - 200
         // this reply is ok
         break;
   }
   case Constants.SERVICE_NOT_AVAILABLE_CODE:
   case Constants.PERMANENT_NEGATIVE_COMPLETION_REPLY_CODE:
   case Constants.SYNTAX_ERROR_IN_ARGUMENTS_CODE:
   case Constants.NOT_LOGGED_IN_CODE:
   {
         throw new FtpException (this, FtpWebResponse.Code,
               FtpWebResponse.GetOriginalMessage(), false);
   }
   default:
   {
   throw new FtpException (this, FtpWebResponse.Code,
   NotValidReplyCodeMessage(FtpWebResponse.Code, "PORT"),
   true); // log this error!!!!!
   }
   

Here I show a custom FTP exception class passing in the response code, an appropriately returned code description, and the source of the error. In the default section of the switch case statement, the developer wishes to log this exception. In the case statement directly above the default, the FtpException (for whatever reason) does not log. This is an imaginary scenario, but it quickly shows how to specify which exceptions are logged and which ones aren't. The logging itself is handled by the exception, as we have seen. But where does the error actually get logged?

Determining Where to Log (Using the Trace Object)

In the BaseException class, logging output is eventually written to one or more log targets using the statement Trace.WriteLineIf(). Here I use the tracing capabilities of the FCL to determine where to send the output. You can easily write to the Windows event log, a log file, or another target directly but I wanted to leverage what I consider one of the more elegant features of .NET—tracing.

// write to all trace listeners
Trace.WriteLineIf(Config.TraceLevel.TraceError, sMessage);

The .NET Trace class methods can be used to instrument any debug or release build of your application. Tracing can be used to monitor the health of any system during runtime but it can also act as logging mechanism. Whether you use it for logging, monitoring, or both, tracing can be great way to diagnose problems without affecting or even recompiling your application.

The Trace.WriteLineIf method above takes only two arguments. The first is a boolean parameter where I use what is called a TraceSwitch to determine whether I want to trace a message and at what level. Don't worry about the TraceSwitch just yet if you haven't worked with them; I will explain them in the upcoming technology backgrounder. The second parameter is simply the message I want to trace. Trace.WriteLineIf() is called from within the Dump method. The Dump method is, in turn, called from within the overloaded BaseException constructor.

Listing 2.5 Sample Base Exception logging routine.

       if (bLog)
       {
             // trace listeners should already initialized, this
             // is called to be prudent
             Utilities.InitTraceListeners();

             // log it
             Dump(Format(oSource, nCode, sMessage,
oInnerException));
       }

You'll also notice a few other goodies in the BaseException class. In Listing 2.5, you see that the Dump method calls the Format method. This method is used to prepare the output format of the error message. How you format your messages and what information is included is completely design-specific. Here my formatted message prepares a string that includes three main parts. The first part is the source of the error, usually passed in as this so that I can access the fully qualified type as well as other elements of the calling object. The second part is the error code that will be ultimately included in the recorded message. The third part is an error summary, which is the description of the error provided by the thrower. This is one set in the exception thrown that will actually be logged. The final parameter is the chained exception, which is usually the one just caught. This will be used to build our error stack because it will contain any previously caught and chained errors. The .NET framework provides the mechanism to chain and even a stack trace to use but it does not provide a formatted error stack. This is your job. Providing a full error stack each time you log is optional but it will help determine the cause of the error. This is in case the high-level error does not provide enough clues as to the cause. In fact, I'm sure you have already found that it typically doesn't.

Determining What to Log

Provide Enough Information

When building your application exception classes, especially your base exception class, you will need to determine how much information to provide. Determining this completely depends on the audience. When providing error information to users, you want to give them enough information to determine that there is a problem without inundating them with terse language or technical details that they may not understand. However, this does not mean you forgo technical information as part of your exception. This only means you do not want to display it by default. For example, when displaying an error dialog, you should show only a high-level version of the problem. Optionally, you can also add a Details button to allow the more technically savvy user get more detailed error information if he or she so chooses. You want to provide the option of information without intimidation.

Providing a high-level error description is typically the job of the last handler of the exception. This is referred to as the exception boundary. This could be an ASP.NET page or a GUI catching the final exception and displaying it to the user. Again, this does not in any way mean you forgo providing rich information; in fact, you should side on providing more rather than too little. Just hide the complexity from the user. One of the great things about .NET is that you don't have to provide rich information through extensive custom development. The FCL takes care of providing you with helper objects and methods that will give you as much relevant data as you can handle. The following table shows some of the informational items you can easily access using the FCL:

Table 2.1. Environmental information: Some examples of information providers from the FCL

You'll notice in Table 2.1 that a couple of the items are retrieved using .NET Reflection. Reflection services allow you introspect the public members of almost any class, including the System.Exception class. This can come in very handy when displaying detailed information during logging or display and should be explored. For more information on Reflection services, please refer to the technology backgrounder on Reflection in Chapter 4.

Building an Error Stack

One of the first things I typically provide is an error stack. This is not to be confused with a call stack; something the System.Exception class provides “out of the box.” As mentioned earlier, the error stack is built around another nice feature of .NET called exception chaining. This is actually a well-known design pattern that the .NET System.Exception class provides for free. All you have to do is take advantage of it. This means making sure during each throw of your BaseException that you pass in the exception class initially caught, as in the following snippet:

catch(FtpException ftpe)
{
      throw new BaseException(this, 1234, "FTP Error: " +
                  ftpe.Message, ftpe, true);
   }
   

Here I am throwing a new exception, passing in a source object (this), an error code (1234), an error description, and what is now the inner exception. In this case, that inner exception is an FtpException. The last parameter (true) will tell this exception to log itself. This will eventually lead to the BuildErrorStack method being called. This is the heart of this method. The BuildErrorStack method simply loops through each chained exception, using the inner exception property of the BaseException class, as shown in Listing 2.6. The format and additional items you place here are, again, up to you. The point is that you leverage the FCL chaining facility by building a useful display medium that will hopefully help solve the issue.

Listing 2.6 Sample stack builder used in our base exception class.

if (oChainedException != null)
{
      sbErrorStack.Append("Error Stack \n")
                  .Append("------------------------\n");

      oInnerException = oChainedException;
      while (oInnerException != null)
      {
            sbErrorStack.Append(nErrStackNum)
                        .Append(") ")
                .Append(oInnerException.Message)
                        .Append("\n");

            oInnerException =
                  oInnerException.InnerException;

            nErrStackNum++;
      }

      sbErrorStack.Append("\n----------------------\n")
                  .Append("Call Stack\n")
          .Append(oChainedException.StackTrace);

      sErrorStack = sbErrorStack.ToString();

}

Throwing System Exceptions

Once you've built your base exception class and all of its helpers, you are probably going to want to leverage it as much as possible. That said, you may also want to take advantage of some of the system exception classes (e.g., System.IOException) that the FCL has to offer. How does one leverage the features of both? The answer is that you use both by employing exception wrapping. When you want to throw a system exception and still want to take advantage of your base exception features, you simply create a new system exception class and pass that as the inner exception of your base exception class constructor. This in effect “wraps” the system exception, allowing it to appear neatly as part of your error stack. This can all be with one (albeit long) line of code:

throw new BaseException(this, 120, GetMessage(120),
new System.IOException(), true);

Here I want to throw the system exception IOException. However, I still want to use my BaseException class features, such as error stacks, message formatting, and logging. Using exception wrapping, I get both.