Click here to Skip to main content
Click here to Skip to main content

Grouping application traces using ActivityId (System.Diagnostics)

By , 31 May 2012
Rate this:
Please Sign up or sign in to vote.

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: 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 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: http://lowleveldesign.codeplex.com.


Filed under: CLR, CodeProject, Profiling, Tracing

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)

About the Author

Sebastian Solnica
Software Developer (Senior)
Poland Poland
Interested in tracing, debugging and performance tuning of the .NET applications (especially ASP.NET).
 
If you find this article interesting, maybe you would like to pay me a visit: http://lowleveldesign.wordpress.com? Smile | :)

Comments and Discussions

 
QuestionNice PinmemberMember 4558661-Jun-12 4:19 
Nice
Rand

AnswerRe: Nice PinmemberSebastian Solnica4-Jun-12 6:02 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.

| Advertise | Privacy | Mobile
Web04 | 2.8.140421.2 | Last Updated 1 Jun 2012
Article Copyright 2012 by Sebastian Solnica
Everything else Copyright © CodeProject, 1999-2014
Terms of Use
Layout: fixed | fluid