Debug notes

I don’t need to stress how tracing (logging) is important in any application. Without logs we are often unable to diagnose the cause of the failure. Logs also help us track application behavior and usage over time. Fortunately there are numerous libraries (including .NET framework itself) that can help us create meaningful logs. In this post I would like to show you how to, using System.Diagnostics classes, nicely group application traces by activities to which they correspond.

Let’s assume we need to write an ordering system. Its basic tasks will be to take some data describing the order, do some processing (process payments, gather additional data from databases or another systems, send mails etc.) and place the order in the database. Depending on how complicated the “do some processing” phase is, there are some places where things could go wrong. If this happens, you could inform the client that his order could not be processed and ask him to try again (but is it really his fault that your system is buggy?) or you can save the order in the database with some error status and an error message and ask your support for further investigation. If you care about your clients you would probably take the second approach. So the support guy ends up with an error message from which (s)he needs to deduce the real cause of the fault. The error message will be most probably the exception name and its stack trace which for production systems (because of the RELEASE build) might not be really useful. So what we need here is some kind of a trace demonstrating what happened in the system before the break. Look at the PlaceOrder method in the code below:

    public sealed class OrderingSystem 
    {
        private const int MaxStatusMessageLength = 2000;
        private static readonly TraceSource logger = new TraceSource("OrderingSystem");
    
        public int PlaceOrder(String username, String product, decimal cash) 
        {
            // create an order record
            var order = new Order {
                            Username = username,
                            Product = product,
                            Cash = cash,
                            CreatedOn = DateTime.UtcNow,
                        };
        
            // validation: if order is invalid throw some exception - ask client to correct
            if (String.IsNullOrEmpty(username)) {
                logger.TraceEvent(TraceEventType.Warning, 0, "Invalid username in order: {0}", username);
            }
            logger.TraceEvent(TraceEventType.Information, 0, "Order validated successfully");

            try {
                // connect with the storehouse system and reserve one item
                var storehouseUrl = "http://storehouse.example.com/ReserveItem?product=" + product;
                logger.TraceInformation("Connecting with the ordering system: {0}", storehouseUrl);
                // TODO: actucal connection with the url
                
                // send email to the delivery (or create a task or database record etc.)
                var email = "chiefOfDelivery@example.com";
                logger.TraceInformation("Informing a chief of delivery: {0}", email);
                // TODO: send email
                
                order.Status = "OK";
            } catch (Exception ex) {
                logger.TraceEvent(TraceEventType.Critical, 0, 
                        "Exception occured while trying to place the order: {0}", ex);
                order.Status = "FAIL";
                order.StatusMessage = ex.ToString();
                if (order.StatusMessage.Length > MaxStatusMessageLength) {
                    order.StatusMessage = order.StatusMessage.Substring(0, MaxStatusMessageLength);
                }
            }
            
            // save record to the database
            using (var conn = new SqlConnection(ConfigurationManager.ConnectionStrings["conn"].ConnectionString)) {
                conn.Open();
                order.Id = (int)conn.Insert(order);
                return order.Id;
            }
        }
    }

Did you see the problem with logs generated by this code? After all we have the order in the database, we have detailed logs so we should be able to investigate the issue. Now, imagine this method is called 20 times every second and so the log record starts growing really fast. How will you find the lines that characterize one particular order? It will be really hard, isn’t it? To resolve this issue we may append the order ID to every log message we produce (so we need to change the code in many places) – but what if our order ID is an identity that we know only after we save it to the database? In that case we probably would require some ID generator. Fortunately we can easily do this using mechanisms that .net framework provides. There is a class called CorrelationManager that, citing MSDN, correlates traces that are part of a logical transaction. It does so by using two static (or rather thread-static) properties: LogicalOperationStack and ActivityId. I usually use only the ActivityId to group the traces (but you may also use the LogicalOperationStack for a better granularity). ActivityId is just a GUID number which lives in the current thread context and can be easily accessed by any TraceListener. It is enough to just set its value at the beginning of your method and restore the previous value when the method ends:

public int PlaceOrder(String username, String product, decimal cash) 
{
  Guid prevActivityId = Trace.CorrelationManager.ActivityId;
  Trace.CorrelationManager.ActivityId = Guid.NewGuid();
  ...
  Trace.CorrelationManager.ActivityId = prevActivityId;
  return order.Id;
}      

You need then to enable tracing for your application (through the app/web.config) and choose the TraceListener that is “activity aware”, such as XmlWriterTraceListener or RollingXmlTraceListener, SqlDatabaseTraceListener (from the excellent EssentialDiagnostics library):

<?xml version="1.0"?>
<configuration>
  <connectionStrings>
    <add name="conn" connectionString="server=localhost\SQLEXPRESS;database=ordersdb;Trusted_Connection=true" providerName="System.Data.SqlClient" />
    <add name="diagnosticsdb" connectionString="server=localhost\SQLEXPRESS;database=diagnosticsdb;Trusted_Connection=true" providerName="System.Data.SqlClient" />
  </connectionStrings>
  <system.diagnostics>
    <trace autoflush="true" />
    <sources>
      <source name="OrderingSystem" switchValue="Verbose">
        <listeners>
          <add name="sqldatabase"
                type="Essential.Diagnostics.SqlDatabaseTraceListener, Essential.Diagnostics"
                initializeData="diagnosticsdb"
                applicationName="OrderingSystem" />
        </listeners>
      </source>
    </sources>
  </system.diagnostics>
</configuration>

The last step is to save the ActivityId in the order entity and so correlate your order with its traces:

public int PlaceOrder(String username, String product, decimal cash) 
{
  Guid prevActivityId = Trace.CorrelationManager.ActivityId;
  Guid activityId = Guid.NewGuid();
  Trace.CorrelationManager.ActivityId = activityId;
  // create an order record
  var order = new Order {
                  Username = username,
                  Product = product,
                  Cash = cash,
                  CreatedOn = DateTime.UtcNow,
                  ActivityId = activityId
              };
  ...
  Trace.CorrelationManager.ActivityId = prevActivityId;
  return order.Id;
} 

If we would like to be fully-compliant with the Microsoft’s tracing standard our PlaceOrder function beginning and ending should look as follows:

Guid prevActivityId = Trace.CorrelationManager.ActivityId;
Guid activityId = Guid.NewGuid();
logger.TraceTransfer(0, "Starting the PlaceOrder method", activityId);
Trace.CorrelationManager.ActivityId = activity;
logger.TraceEvent(TraceEventType.Start, 0, "start");
...
logger.TraceTransfer(_transferOutId, "Finishing method", prevActivityId);
logger.TraceEvent(TraceEventType.Stop, 0, "stop");
Trace.CorrelationManager.ActivityId = prevActivityId;

Pretty tedious, isn’t it? Fortunately we can use the ActivityScope class, again from the Essential.Diagnostics library, which emits this code for us:

public int PlaceOrder(String username, String product, decimal cash) 
{
    using (new ActivityScope(logger)) {
        // create an order record
        var order = new Order {
                        Username = username,
                        Product = product,
                        Cash = cash,
                        CreatedOn = DateTime.UtcNow,
                        ActivityId = Trace.CorrelationManager.ActivityId
                    };
    ....
    }
}

After the last improvement if our method ever happens to be a part of the WCF request, its traces will nicely wrap into the WCF tracing model:

I hope that I have encouraged you to use the tracing methods provided by the framework. They are highly configurable allowing you to dynamically add/remove trace listeners without changing the application code. If you are logging to a database you may want to filter the events to only very important sources (like OrderingSystem in our case). When something is going wrong in your system or you need more verbosity of traces you can always add System.Diagnostics.EventProviderTraceListener which uses the ETW infrastructure to save traces. ETW is known to have a very low impact on application performance and so can be safely used for short-time verbose tracing on production systems. As usual all source code is available for download on my codeplex sample page: http://lowleveldesign.codeplex.com.