Grouping Application Traces using ActivityId (System.Diagnostics)

Introduction

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 to track the application behavior and usage over time. Fortunately, there is a great bunch of 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 that they correspond to.

Let’s assume that we need to write an ordering system. Its basic tasks will be to take some data describing the order, do some processing (proceed payment, gather additional data from the 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 a 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 the production systems (because of the RELEASE build) might not be really useful. So what we need here is some kind of a trace 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: actual 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 pretty detailed logs so we should be able to investigate the issue. Now, imagine that 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 do much easier 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 would be 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 full-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 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 is using the ETW infrastructure to save traces. ETW is known to have a very low impact on the 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.

History

• 1^st June, 2012: Initial version