By the time you have read through the previous four posts, you should be able to create end-to-end Traces for your applications:

In the first posting we introduced the new .NET (2.0+) Trace framework and talked about the features that make it a comprehensive Tracing tool. We then went on to look at more advanced usage and configuration in the second posting, particularly around the XmlWriterTraceListener and the Microsoft Service Trace Viewer. The third posting looked at Activity Tracing, Activity Propagation and WCF Activity Tracing. The fourth posting looked at how to propagate Trace information to HTTP based endpoints such as ASP.NET and ASP.NET MVC.

Using Resource Objects

You will start to see you code can become quite complex as you add Activity tracing information; this is due to having to close off any Start or Transfer Activity. To ensure you close off any Starts or Transfers, you need to make sure you catch any errors and in the finally section of the code call the appropriate Stop or Transfer back.

TraceSource traceSource = new TraceSource("DemoApp");

try
{
  traceSource.TraceEvent(TraceEventType.Start, 0, "Start activity here ...");
}
finally
{
  traceSource.TraceEvent(TraceEventType.Stop, 0, "Stop activity here ...");
}

The alternative to this approach is to use a Disposable object and call it as part of a resource object pattern. In this case, the code is much cleaner and simpler to read and implement. The following classes provide resource containers for Start and Transfer activities so that they can be encapsulated in a using statement:

TraceLogicalScope

The TraceLogicalScope class provides a simple and safe way to encapsulate a Start and Stop activity.

/// <summary>
/// Represents a Trace Start/Stop where the Start and Stop are called automatically
/// </summary>
public class TraceLogicalScope : IDisposable
{
  /// <summary>
  /// The source that we are tracing through as part of this scope
  /// </summary>
  private readonly TraceSource _traceSource;

  /// <summary>
  /// The name of the logical block that this scope represents
  /// </summary>
  private readonly string _logicalName;

  /// <summary>
  /// Constructor used to initialize the class
  /// </summary>
  /// <param name="traceSource">The source that we are tracing through as part of this scope</param>
  /// <param name="logicalName">The name of the logical block that this scope represents</param>
  public TraceLogicalScope(TraceSource traceSource, string logicalName)
  {
    if (traceSource == null)
    {
      throw new ArgumentNullException("traceSource");
    }

    if (string.IsNullOrEmpty(logicalName))
    {
      throw new ArgumentNullException("logicalName");
    }

    _traceSource = traceSource;
    _logicalName = logicalName;

    _traceSource.TraceEvent(TraceEventType.Start, 0, "Starting " + _logicalName);
  }

  /// <summary>
  /// Called when the object is cleaned up, to close the scope
  /// </summary>
  public void Dispose()
  {
    _traceSource.TraceEvent(TraceEventType.Stop, 0, "Stopping " + _logicalName);
  }
}

TraceTransferScope

The TraceTransferScope class provides a simple and safe way to encapsulate a Transfer to and from an activity.

/// <summary>
/// Represents a Trace Transfer scope within which tracing Transfers to and from another Activity
/// </summary>
public class TraceTransferScope : IDisposable
{
  /// <summary>
  /// The activity ID that we stitched away from when this scope was started
  /// </summary>
  private readonly Guid _oldActivityId;

  /// <summary>
  /// The activity ID that we stitched to when this scope was started
  /// </summary>
  private readonly Guid _newActivityId;

  /// <summary>
  /// The source that we are tracing through as part of this scope
  /// </summary>
  private readonly TraceSource _traceSource;

  /// <summary>
  /// The name of the activity that this scope represents
  /// </summary>
  private readonly string _activityName;

  /// <summary>
  /// Constructor used to initialize the class
  /// </summary>
  /// <param name="traceSource">The source that we are tracing through as part of this scope</param>
  /// <param name="activityName">The name of the activity that this scope represents</param>
  public TraceTransferScope(TraceSource traceSource, string activityName)
  {
    if (traceSource == null)
    {
      throw new ArgumentNullException("traceSource");
    }

    if (string.IsNullOrEmpty(activityName))
    {
      throw new ArgumentNullException("activityName");
    }

    _traceSource = traceSource;
    _oldActivityId = Trace.CorrelationManager.ActivityId;
    _activityName = activityName;

    _newActivityId = Guid.NewGuid();

    if (_oldActivityId != Guid.Empty)
    {
      _traceSource.TraceTransfer(0, string.Format("Transferring to {0}...", _activityName), _newActivityId);
    }

    Trace.CorrelationManager.ActivityId = _newActivityId;

    _traceSource.TraceEvent(TraceEventType.Start, 0, _activityName);
  }

  /// <summary>
  /// Called when the object is cleaned up, to close the scope
  /// </summary>
  public void Dispose()
  {
    if (_oldActivityId != Guid.Empty)
    {
      _traceSource.TraceTransfer(0, string.Format("Transferring back from {0}...", _activityName),  _oldActivityId);
    }

    _traceSource.TraceEvent(TraceEventType.Stop, 0, _activityName);

    Trace.CorrelationManager.ActivityId = _oldActivityId;
  }
}

Example

The following shows the same Start/Stop example from the top of the psoting using the new TraceLogicalScope class:

TraceSource traceSource = new TraceSource("DemoApp");

using (new TraceTransferScope(traceSource, "new activity"))
{
  // Perform the new, transferred activity here and Trace will be
  // written against the new Activity automatically, and switched back to
  // the original Activity when we drop out of this scope ...
}

Conclusion

Hopefully these classes should prove invaluable if you are instrumenting your code with Trace and Activity information.

P.N.

In the first posting we introduced the new .NET (2.0+) Trace framework and talked about the features that make it a comprehensive Tracing tool. We then went on to look at more advanced usage and configuration in the second posting, particularly around the XmlWriterTraceListener and the Microsoft Service Trace Viewer. The third posting looked at Activity Tracing, Activity Propagation and WCF Activity Tracing.

This fourth posting looks at how we can propagate Activity information to ASP.NET / ASP.NET MVC end points to again create end-to-end Trace results for complete diagnosis of an application.

ActivityId Propagation

Unlike WCF, there is currently no way to automatically propagate an ActivityId to an ASP.NET based end point. So, the first thing we need to do is figure out how this will work.

The usual way to pass supplementary information or parameters to an end point as part of a HTTP request/response, is through a HTTP header. A HTTP header is a simple name-value pair that isn’t required to actually make the call but can be read by the client or server if it is present. We can use a HTTP header to pass our ActivityId to an ASP.NET based, or any other end point for propagation purposes.

Currently, there is no defined, standard HTTP header for identifying an ActivityId; this means we will need to define something ourselves. Additionally, outside of the .NET Trace framework which uses ActivityIds, end-to-end Tracing usually uses a “Correlation ID“ for correlating information between systems. In the example code below we are going to use a “Correlation-ID” HTTP header to pass the Trace ActivityId to our end points (this can of course be anything you want).

Adding the Header

Adding a header to an HTTP call in .NET is trivial, as is adding the ActivityId. The following code can be used to achieve this.

WebRequest webRequest = HttpWebRequest.Create(url);
webRequest.Headers.Add("Correlation-ID", Trace.CorrelationManager.ActivityId.ToString());

It is possible to use a tool like Fiddler to see the newly added HTTP header. The following shows an example of a call to a local ASP.NET end point using the code above.

GET <a href="http://localhost/propcorrid">http://localhost/propcorrid</a> HTTP/1.1
Accept: application/xml
Correlation-ID: 51e81973-a7d3-44e9-929a-a9b962a01dbd
Host: localhost
Connection: Keep-Alive

Reading the Header

Ideally, we want our ActivityId to be associated with the Trace framework before we get to our ASP.NET/MVC code; this would mean we just instrument our code with no regard for being in a different process and the Trace output can be followed end-to-end. This is easily achieved through the HTTP Pipeline and IHttpModule framework.

An HttpModule is able to process the HTTP request before it ends up at the ASPX page / MVC Controller or other endpoint. At this point we can look for the “Correlation-ID” header that was passed as part of the request and re-assign it to the Trace framework. This means that the ActivityId would be in place before it got to the ASPX page / MVC Controller or other endpoint. The following code is a complete HttpModule that can be used for ActivityId assignment:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using System.Web;
using System.Diagnostics;
using System.Configuration;
namespace AssemblyNameHere
{
  /// <summary>
  /// Http Module that is used to add additional trace information to an application, and automatically wire up
  /// passed correlation IDs
  /// </summary>
  public class ActivityTraceModule : IHttpModule
  {
    /// <summary>
    /// The specific trace source used to trace data to
    /// </summary>
    static TraceSource _traceSource = new TraceSource("AssemblyNameHere");

    /// <summary>
    /// The name of the header used to check for passed Correlation IDs
    /// </summary>
    private string _headerName;

    /// <summary>
    /// Called through the interface to initialize this module when it is first loaded
    /// </summary>
    /// <param name="app">The application that modeule is being loaded into</param>
    public void Init(HttpApplication app)
    {
      app.BeginRequest += app_BeginRequest;
      string headerName = "Correlation-ID";
      string temp = ConfigurationManager.AppSettings["TraceModuleCorrelationHeader"];
      if (String.IsNullOrEmpty(temp) == false)
      {
        headerName = temp;
      }

      _headerName = headerName;
    }

    /// <summary>
    /// Called to clean up any resources this object maintaines
    /// </summary>
    public void Dispose()
    { }

    /// <summary>
    /// Called when a new request is started in the application
    /// </summary>
    /// <param name="sender">The sender of the event</param>
    /// <param name="e">Any arguments passed by the sender</param>
    void app_BeginRequest(object sender, EventArgs e)
    {
      HttpApplication app = (HttpApplication)sender;
      HttpContext context = app.Context;
      IEnumerable<string> headerValues = context.Request.Headers.GetValues(_headerName);
      Guid activityId;
      if (headerValues != null)
      {
        int count = headerValues.Count();
        bool createNewActivity = true;
        if (count > 0)
        {
          if (count > 1)
          {
            _traceSource.TraceEvent(TraceEventType.Warning, 0, "Unable to set the activityId as there are multiple values");
          }
          else
          {
            if (Guid.TryParse(headerValues.ElementAt(0), out activityId))
            {
              // We have been passed a valid ActivityId
              Trace.CorrelationManager.ActivityId = activityId;
              createNewActivity = false;
            }
            else
            {
              _traceSource.TraceEvent(TraceEventType.Warning, 0, "Unable to parse the activityId as it is not a Guid");
            }
          }
        }
        if (createNewActivity)
        {
          // No ActivityId was passed so create a new one
          Trace.CorrelationManager.ActivityId = Guid.NewGuid();
        }
      }
    }
  }
}

There are three points to note about the code above:

• Firstly, remember how we discussed that the namespace of the code should be used for the name of the TraceSource so that other developers know how to configure the listeners for any code well, in the case above, the AssemblyNameHere needs to be changed to your namespace.
• Secondly, as this is generic code, it has been written to support any Correlation-ID name for the HTTP Header and this can be changed from the default “Correlation-ID” using a web.config appSetting called “TraceModuleCorrelationHeader”.
• Thirdly, if no ActivityId is received at the HttpModule, one is created and applied to the Trace.CorrelationManager.ActivityId. The reason for this is that all of the subsequent code will be related to this starting point rather than having all activity grouped under an empty Guid.

Configuration

Configuring the Trace framework works in exactly the same way as in the previous posts. The following shows the KEY areas of the configuration file for working with the Tracing framework and the HttpModule. NOTE: additional configuration not related to Tracing has been removed, things like pages, namespaces, debug options etc.

The following shows a typical configuration including the HttpModule section. NOTE: You need to swap the AssemblyNameHere placeholders for the name of your assembly.

<configuration>
  <appSettings>
    <add key="TraceModuleCorrelationHeader" value="Correlation-ID" />
  </appSettings>
  <system.webServer>
    <validation validateIntegratedModeConfiguration="false" />
    <modules runAllManagedModulesForAllRequests="true">
      <add name="QuantivTraceModule"
        type="AssemblyNameHere.ActivityTraceModule, AssemblyNameHere"/>
    </modules>
  </system.webServer>
  <system.diagnostics>
    <sources>
      <source name="AssemblyNameHere" switchValue="Verbose, ActivityTracing">
        <listeners>
          <add name="xml" />
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add name="xml"
        initializeData="C:\logs\web.svclog"
        type="System.Diagnostics.XmlWriterTraceListener"
        traceOutputOptions="Callstack" />
    </sharedListeners>
    <trace autoflush="true">
      <listeners>
        <add name="xml"/>
      </listeners>
    </trace>
  </system.diagnostics>
</configuration>

Microsoft Service Trace Viewer

Again, we have looked at the Microsoft Service Trace Viewer in previous posts so please check back for an introduction. One of the really powerful features of the Microsoft Service Trace Vieweris that you can open multiple files and combine the results – this is the basis of the end-to-end tracing.

When we call an ASP.NET/MVC end point, we typically do so from a client different process. The Client process runs in one process space and can write Trace information to its own XML file through the XmlWriterTraceListener. Using the configuration above, an ASP.NET/MVC end point running in a w3wp process can also dump to its own XML file through the XmlWriterTraceListener. If we have passed the ActivityId correctly, the different files will contain the same ActivityIds and can therefore be combined to show the Trace Activity flow.

Using the Microsoft Service Trace Viewer, we can open both the client and the ASP.NET/MVC XML files and see the comdined results. The following screen shows the complete end-to-end Activity Trace output and you can clearly see the w3wp Process Name being used for the Request/Response logging.

Conclusion

In this posting you should have seen how to pass Activity tracing information to any end point through HTTP headers, and also how to configure an ASP.NET/MVC application to check for and wire-up received ActivityIds.

One final posting will follow this with a couple of utility classes that can be used for Trace Scopes.

P.N.

In the first posting we introduced the new .NET (2.0+) Trace framework and talked about the features that make it a comprehensive Tracing tool. We then went on to look at more advanced usage and configuration in the second posting, particularly around the XmlWriterTraceListener and the Microsoft Service Trace Viewer.

This posting builds on the previous ones and starts to look at how to instrument some code so that the logical flow can be followed, how to propagate information across process and machine boundaries for end-to-end processing, how this can be automatically supported in WCF and how we can view end-to-end trace information using the XmlWriterTraceListener and the Microsoft Service Trace Viewer.

TraceEventType Revisited

We have already seen how the TraceEventType enumeration provides us with severity levels for trace events, and how we can control the events that are recorded by the Trace Listeners through Trace Switches and Filters. The TraceEventType also contains Activity event types for Activity and end-to-end Tracing.

Activity Tracing is added to code to define the logical flow through an application; when specific areas of processing are being started and finished, or processing is switching between processes or machines. The TraceEventTypes enum contains additional entries to identify these areas of the code:

• Start – a logical operation is being started such as an update to the database
• Stop – a logical operation has completed
• Suspend – a logical operation is being suspended, typically because processing has been passed on to say a web service call
• Resume – a logical operation is being resumed, typically because processing has returned to this code
• Transfer – processing is being transferred from one logical operation (or process/machine boundary) to another

Activity Tracing

The first thing to note about Activity Tracing is that it needs to be switched on in the application’s configuration file (app.config or web.config) before it is sent to the Listeners. Where we have previously used a switchValue in the configuration files to define the level at which the Listeners receive the events, we also need to add an ActivityTracing level:

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Verbose, ActivityTracing">
        <listeners>
          <add name="xml"/>
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add name="xml"
        type="System.Diagnostics.XmlWriterTraceListener"
        initializeData="C:\logs\DemoApp.svclog" />
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

Instrumenting an application with Activity Tracing logic is exactly the same as recording other TraceEvents. For example, the following shows how to Start and Stop a new logical operation:

TraceSource ts = new TraceSource("DemoApp");
ts.TraceEvent(TraceEventType.Start, 0, "Starting database update");
// Update the database
ts.TraceEvent(TraceEventType.Stop, 0, "Completed database update");

If we run this code with the configuration above, and open the C:\logs\DemoApp.svclog XML file in the Microsoft Service Trace Viewer we see the following:

You can see that the individual traces appear under the same single Activity in the left hand pane called “Starting Database …”. Each individual Trace event is grouped using a Guid that is assigned in the Trace.CorrelationManager. To start a new Activity, a new Guid must be created and assigned using the following code:

Trace.CorrelationManager.ActivityId = Guid.NewGuid();

Typically, a new Activity is started at the outer most point in the code, such as a postback entry point in a website, a REST API call or a WCF service call; Activities here typically represent specific Use Cases or User Stories for the application. This single Activity then contains all of the Trace records that were created under this Activity so the entire call history through the code can be grouped together and analysed. If our code represents a business process of creating a customer, for example, we would have some (very simplified code) that looks like the following:

TraceSource ts = new TraceSource("DemoApp");

// Start the new Create Customer Activity
Trace.CorrelationManager.ActivityId = Guid.NewGuid();
ts.TraceEvent(TraceEventType.Start, 0, "Starting Create Customer Activity");
// Check received customer data
ts.TraceEvent(TraceEventType.Information, 1, "Customer data is valid");
ts.TraceEvent(TraceEventType.Start, 2, "Starting check if the customer exists");
// Code to check if customer exists (this may also trace events under this activity)
ts.TraceEvent(TraceEventType.Information, 3, "Customer does not exists");
ts.TraceEvent(TraceEventType.Stop, 4, "Finsihed check if the customer exists");
ts.TraceEvent(TraceEventType.Information, 5, "Adding customer to the database");
ts.TraceEvent(TraceEventType.Start, 6, "Starting add customer to the database");
// Code to add customer to the database (this may also trace events under this activity)
ts.TraceEvent(TraceEventType.Stop, 7, "Finishing add customer to the database");
ts.TraceEvent(TraceEventType.Information, 8, "Added customer to the database");
ts.TraceEvent(TraceEventType.Stop, 9, "Completed Create Customer Activity");

If we run this code four times, and the third call fails due to an error, we would see the following in the Microsoft Service Trace Viewer. As you can see, this provides a comprehensive view of the logic in the code.

In the above screenshot, each time the Create Customer code is called, a new Activity is added in the viewer. All of the events that are recorded under this activity are then seen on the right of the screen, grouped under this Activity. You can clearly see the logical areas of the code starting and stopping. During the execution of the third Activity, one of the events was an error so the Activity is shown in red.

Activity Propagation

So, each individual Activity uses a single ActivityId which is assigned to the Trace.CorrelationManager.ActivityId. As events are recorded, this ActivityId is added to the Trace output and the Microsoft Service Trace Viewer uses this to group information when it is displayed. Changing this Guid effectively starts a new Activity, as discussed above.

It is also possible to assign an existing Guid to the Trace.CorrelationManager.ActivityId. This means if we are able to pass an ActivityId from one process or machine to another, and re-assign it to the Trace.CorrelationManager.ActivityId before we begin to Trace again, then all of our end-to-end processing will appear under the same ActivityId in the Microsoft Service Trace Viewer. It’s that simple!

WCF Activity Propagation

WCF supports Activity Propagation out of the box, through configuration.

We have previously stated that the TraceSource name that should used when writing Trace information should be the name of the assembly the code resides within. We have previously used “DemoApp” but in the case of the WCF framework, the “System.ServiceModel” TraceSource is used for Tracing information. Following this approach means we can simply configure our application to Trace output from the WCF framework itself. The following shows how this is achieved, with anything at an Information level or above and ActivityTracing events being recorded.

<configuration>
  <system.diagnostics>
    <sources>
      <source name="System.ServiceModel"
        switchValue="Information, ActivityTracing"
        propagateActivity="true">
        <listeners>
          <add name="xml"
            type="System.Diagnostics.XmlWriterTraceListener"
            initializeData= "c:\log\Traces.svclog" />
        </listeners>
      </source>
    </sources>
  </system.diagnostics>
</configuration>

Microsoft provides recommendations for Production and Deployment configurations: http://msdn.microsoft.com/en-us/library/aa702726.aspx

Line 6 above shows how the WCF Framework can be configured to automatically pass the ActivityId between two end points. When propagateActivity is set to “true”, the ActivityId is added to the WCF payload when the call is made and the framework automatically checks for the passed ActivityId and applies it at the receiver using:

Trace.CorrelationManager.ActivityId = receivedActivityId;

The WCF framework also creates Start and Stop events at the relevant points to provide a detailed view of the calls with no additional code being required. The following shows an example of just how detailed the WCF Tracing can be in the Microsoft Service Trace Viewer’s Graph view:

Trace Transfers

Another feature of the Tracing framework for Activity tracing is to be able to transfer processing from one Activity to another. In this scenario, each individual Activity is displayed in the left of the Microsoft Service Trace Viewer UI, but a connection is also added between the individual Activities where the transfer takes place. Having the Transfer recorded means that the initial Activity can also display the Activity that was transferred to as part of its graph.

As an example, imagine we have some code that debits a user account. Imagine we also have some generic code that emails the user with their current balance. These are two separate Activities and should be recorded as such in the Trace output. However, we also want to make sure the email output is also recorded as part of the DebitAccount activity so we can follow all of this code flow. The following shows the instrumented code for this:

private static void DebitAccount(int amount)
{
  // Start a new debit activity
  Guid debitGuid = Guid.NewGuid();
  Trace.CorrelationManager.ActivityId = debitGuid;

  TraceSource ts = new TraceSource("DemoApp");
  ts.TraceEvent(TraceEventType.Start, 0, "Starting Debit the account");
  ts.TraceEvent(TraceEventType.Information, 1, "The account has been debited");

  // Create a new ActivityId and Transfer to it
  Guid emailGuid = Guid.NewGuid();
  ts.TraceTransfer(0, "Transferring to Email the user", emailGuid);
  // Actually switch the Guid that we trace against
  Trace.CorrelationManager.ActivityId = emailGuid;

  try
  {
    EmailUser();
  }
  finally
  {
    // Restore the original ActivityId so events are raised in the debit activity
    ts.TraceTransfer(0, "Transferring back to Debit the account", debitGuid);
    Trace.CorrelationManager.ActivityId = debitGuid;
  }

  ts.TraceEvent(TraceEventType.Stop, 5, "Finishing Debit the account");
}

private static void EmailUser()
{
  // Events in here are raised against a different activity
  TraceSource ts = new TraceSource("DemoApp");
  ts.TraceEvent(TraceEventType.Start, 0, "Starting Email the user");
  // Email the user here
  ts.TraceEvent(TraceEventType.Information, 1, "Emailed the user");
  ts.TraceEvent(TraceEventType.Stop, 2, "Finishing Email the user");
}

As you can see below, there are two separate Activities generated by this code. The first activity is the “Debit the account” Activity only. You should be able to see the events Transfer to the “Email the user” event but this is not part of the “Debit the account” Activities event listing.

The second screen shows the “Email the user” activity as a separate Activity. You should be able to see where the events start from a Transfer and at the end they return back to the “Debit the account” Activity.

Finally, the following screen shows the graph view of the “Debit the account” Activity. As you can see, the graph shows all of the calls that formed part of this Activity, including the Transfer to the “Email the user” Activity. Despite there being two discrete Activities, they are related through the Transfer and can be viewed as one.

In Conclusion

In this posting, we have looked at how we can instrument our code to trace Activities through logical areas of applications and across process and machine boundaries, meaning end-to-end Traceability and diagnosis. We have seen how this can be achieved automatically in WCF through configuration. We have also seen how the XmlWriterTraceListener and Microsoft Service Trace Viewer can be used to view the log traces and combine Activities to give a graphical view of an Activity.

In the next posting we will look at how we can propagate ActivityId information to ASP.NET/MVC applications for end-to-end tracing in Web Applications and Web APIs.

A couple of helper classes that will prove useful when using the Trace framework

P.N.

In the previous posting we introduced the new .NET (2.0+) Trace framework and talked about the features that make it a comprehensive Tracing tool.

This posting builds on that information to look at more advanced usage and configuration. You should read the previous posting before embarking on this one.

Configuration Revisited

The code used to Trace is very simple: TraceEvent Traces the information you pass to it; TraceData simply calls ToString on the objects that are passed to it and then calls TraceEvent. It really is that simple!

There are, however, more advanced options for enhancing the Trace output through configuration.

TraceOutputOptions

TraceOutputOptions are used to Trace additional information in the Listeners (some Listeners such as the EventLogTraceListener don’t honour all of these options due to the potential size of the event). There are 6 options for the additional information that can be traced (again, available on MSDN):

• Callstack – Write the call stack, which is represented by the return value of the Environment.StackTrace property.
• DateTime – Write the date and time.
• LogicalOperationStack – Write the logical operation stack, which is represented by the return value of the CorrelationManager.LogicalOperationStack property.
• ProcessId – Write the process identity, which is represented by the return value of the Process.Id property.
• ThreadId – Write the thread identity, which is represented by the return value of the Thread.ManagedThreadId property for the current thread.
• Timestamp – Write the timestamp, which is represented by the return value of the GetTimeStamp() method.

These options are added to the Trace output through the traceOutputOptions attribute of the Listener, as shown below. In this case, the Console will display an additional Timestamp and the XmlWriterTraceListener, which is called only when an error occurs, will also Trace the LogicalOperationStack  and Callstack:

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Verbose">
        <listeners>
          <add name="console"/>
          <add name="xml"/>
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add name="console"
        type="System.Diagnostics.ConsoleTraceListener"
        traceOutputOptions="Timestamp">
        <filter
          type="System.Diagnostics.EventTypeFilter"
          initializeData="Information"/>
      </add>
      <add name="xml"
        type="System.Diagnostics.XmlWriterTraceListener"
        initializeData="C:\logs\DemoApp.svclog"
        traceOutputOptions="LogicalOperationStack,Callstack">
        <filter
          type="System.Diagnostics.EventTypeFilter"
          initializeData="Error"/>
      </add>
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

If we run an application with this configuration, and execute the following line of code:

TraceSource traceSource = new TraceSource("DemoApp");
traceSource.TraceEvent(TraceEventType.Error, 1, "An error occurred contacting the database 'An Exception ...'");

The following is seen in the Console window, with the additional Timestamp being displayed:

DemoApp Error: 1 : An error occurred contacting the database 'An Exception ...'
Timestamp=1133394907677

We are going to look at the XmlWriterTraceListener in more detail below but the following shows the XML that is generated with the ApplicationData element containing the LogicalOperationStack and Callstack elements

<E2ETraceEvent xmlns="<a href="http://schemas.microsoft.com/2004/06/E2ETraceEvent">http://schemas.microsoft.com/2004/06/E2ETraceEvent</a>">
  <System xmlns="<a href="http://schemas.microsoft.com/2004/06/windows/eventlog/system">http://schemas.microsoft.com/2004/06/windows/eventlog/system</a>">
    <EventID>1</EventID>
    <Type>3</Type>
    <SubType Name="Error">0</SubType>
    <Level>2</Level>
    <TimeCreated SystemTime="2012-09-11T15:22:37.3469888Z" />
    <Source Name="DemoApp" />
    <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
    <Execution ProcessName="DemoApp.vshost" ProcessID="13232" ThreadID="9" />
    <Channel/>
    <Computer>ICEBLUE</Computer>
  </System>
  <ApplicationData>
    An error occurred contacting the database &apos;An Exception ...&apos;<System.Diagnostics xmlns="<a href="http://schemas.microsoft.com/2004/08/System.Diagnostics">http://schemas.microsoft.com/2004/08/System.Diagnostics</a>">
      <LogicalOperationStack></LogicalOperationStack>
      <Timestamp>1135474177573</Timestamp>
      <Callstack>   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
at System.Environment.get_StackTrace()
at System.Diagnostics.TraceEventCache.get_Callstack()
at System.Diagnostics.XmlWriterTraceListener.WriteFooter(TraceEventCache eventCache)
at System.Diagnostics.XmlWriterTraceListener.TraceEvent(TraceEventCache eventCache, String source, TraceEventType eventType, Int32 id, String message)
at System.Diagnostics.TraceSource.TraceEvent(TraceEventType eventType, Int32 id, String message)
at ConsoleApplication3.Program.StoreData(Object data) in C:\_RS\ConsoleApplication3\ConsoleApplication3\Program.cs:line 46
at ConsoleApplication3.Program.Main(String[] args) in C:\_RS\ConsoleApplication3\ConsoleApplication3\Program.cs:line 15
at System.AppDomain._nExecuteAssembly(RuntimeAssembly assembly, String[] args)
at System.AppDomain.ExecuteAssembly(String assemblyFile, Evidence assemblySecurity, String[] args)
at Microsoft.VisualStudio.HostingProcess.HostProc.RunUsersAssembly()
at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean ignoreSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.ThreadHelper.ThreadStart()</Callstack>
    </System.Diagnostics>
  </ApplicationData>
</E2ETraceEvent>

Trace Listeners

There are also several additional Listeners that can be configured to run in the Trace framework. In the previous posting we looked at two Trace Listeners that record information in the Console and Event Log. We discussed how these Listeners can be run concurrently so that the same Trace can be output to multiple Listeners simultaneously. We looked at how we can control which Listeners record information for different severity levels. Once the code has been instrumented with Trace calls, we have complete control over where the Trace events are recorded through configuring the Listeners.

There are several other trace listeners provided by the .NET Framework out of the box. These additional Listeners include (this is taken directly from MSDN):

• A TextWriterTraceListener redirects output to an instance of the TextWriter class or to anything that is a Stream class. It can also write to the console or to a file, because these are Stream classes.
• A FileLogTraceListener provides a simple listener that directs logging output to file.
• An EventLogTraceListener redirects output to an event log.
• An EventProviderTraceListener redirects output to the Event Tracing for Windows (ETW) framework. Click for more information on ETW Tracing.
• A DefaultTraceListener emits Write and WriteLine messages to the OutputDebugString and to the Debugger.Log method. In Visual Studio, this causes the debugging messages to appear in the Output window. Fail and failed Assert messages also emit to the OutputDebugString Windows API and the Debugger.Log method, and also cause a message box to be displayed. This behavior is the default behavior for Debug and Trace messages, because DefaultTraceListener is automatically included in every Listeners collection and is the only listener automatically included.
• A ConsoleTraceListener directs tracing or debugging output to either the standard output or the standard error stream.
• A DelimitedListTraceListener directs tracing or debugging output to a text writer, such as a stream writer, or to a stream, such as a file stream. The trace output is in a delimited text format that uses the delimiter specified by the Delimiter property.
• The IisTraceListener routes all tracing and debugging output to the IIS 7.0 infrastructure.
• A WebPageTraceListener directs Trace messages to ASP.NET Web page outputs.
• An XmlWriterTraceListener directs tracing or debugging output as XML-encoded data to a TextWriter or to a Stream, such as a FileStream.

In addition to the Listeners above, there are community projects that provide extensions and additional Listeners. An example of such community work includes:

http://msdn.microsoft.com/en-us/library/ee779630

http://essentialdiagnostics.codeplex.com/

The DefaultTraceListener is automatically added to the Listeners collection when application starts. If you make no configuration changes and simply Trace some events, they will appear in the Visual Studio Output window through this DefaultTraceListener. It is, however, possible to remove the DefaultTraceListener from the collection using the following configuration:

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Verbose">
        <listeners>
          <clear/>
        </listeners>
      </source>
    </sources>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

The Listeners for the Trace framework are pluggable so you can also write your own. This is out of the scope of this posting but in essence you need to create a new class that derives from TraceListener and use the configuration to include this new Listener.

XmlWriterTraceListener

The XmlWriterTraceListener is perhaps one of the most powerful out-of-the-box Trace Listeners available in the .NET Framework. It writes Trace events into a configurable file in an XML format but more importantly there is a supporting client application called the Microsoft Service Trace Viewer which was actually introduced with WCF.

If we open the previous XML output from the C:\logs\DemoApp.svclog file generated above, in the Service Trace Viewer, we see the following detailed breakdown. Our Error message is highlighted in red and the details of the event are decomposed into discrete sections in the UI.

In Conclusion

In this posting we have looked at some of the advanced configuration techniques and Trace Listeners provided by the .NET Trace framework and the different TraceListeners provided out-of-the-box. We have also looked at how we can use the XmlWriterTraceListener and the Microsoft Service Trace Viewer to view detailed Trace events.

In the following postings we will look at:

How we can instrument our code to propagate information across process and machine boundaries and use the XmlWriterTraceListener and the Microsoft Service Trace Viewer to view end-to-end activity

How to pass ActivityIds to ASP.NET/MVC applications for end-to-end tracing in REST

A couple of helper classes that will prove useful when using the Trace framework

P.N.

This, and the next few postings, cover the .NET Framework’s Trace capabilities and explain why you don’t need any third party tools to understand what your code is doing. In particular this posting discusses the Trace framework fundamentals, its features and how to get started.

Background

Microsoft introduced a tracing/diagnostics framework into the first version of .NET through System.Diagnostics.Trace. The Trace framework allowed you to write messages or data to a series of Listeners; Listeners were provided in the .NET Framework and could also be constructed to write to the Event Log, databases, email, files, etc.

This initial Trace framework was pretty light and, as many people adopting .NET were coming from a Java background, this framework wasn’t really deemed powerful enough compared to several of the existing Java frameworks. Several new external frameworks started to appear, Java based frameworks such a log4net and nlog, and the .NET based Enterprise Library Logging Application Block. These frameworks were all very powerful and also tended to be quite complicated to use.

For reference, developers become very passionate about logging and their chosen framework, and as people move around jobs and even departments within the same company, hostility can be encountered!

Revamp

Structurally, the initial version of the Trace framework was pretty sound. In code you could Trace some information. The Trace framework received this information and ran it through a series of configurable Listeners with each one being given the information to record. A single event could be recorded in multiple Listeners simultaneously; in the Event Log, a file and an email for example. This is unchanged.

In the .NET 2.0 release .NET’s Trace framework was revamped to effectively provide most of the functionality you would ever need from a Tracing tool, taking into account the competitor functionality. SourceTypes, Trace Switches and Trace Filters were added as was the ability to track events across process and machine boundaries.

However, there was no song and dance from Microsoft and it was an extension to the existing Trace and .NET framework so no new namespaces or assemblies. The changes went pretty much unnoticed and developers continued to use third party tools.

What’s Nice About Trace

There are obviously powerful new features in the new Trace framework, but there are also a few things that just make the new Trace nice to use compared to third party tools:

There are no extra build, deployment or coding steps required to use Trace as the code is included in the .NET framework. In fact, most projects already reference the correct assembly so simply add a reference to System.Diagnostics and you are away.

The Trace framework can work with third party logging frameworks that support listening for Trace events! So, if you still want to use the appenders or formatters supplied by log4net, for example, then you can, but your code doesn’t need to be littered with log4net references; it is almost impossible to remove a logging provider once it has been added to a codebase!

It really is easy to use. There are a few, simple configuration steps but after that, the code is really easy.

If you are using WCF, it integrates really nicely for propagation of calls through WCF process and machine boundaries.

Finally, one of the most powerful features of the Trace framework is that it is built into the .NET codebase and passes context around behind the scenes. This means it really is possible to follow calls through an entire application, across processes and even across machine boundaries.

What and When and to Trace?

To make it simpler, the question should almost be reversed and be What and When Not to Trace! The more information you Trace the easier it is to understand what is going on in your code and diagnose and resolve any issues. That said, there is a performance hit with continually feeding information to the Trace Listeners but that is where Trace Switches and Filters prove invaluable.

From a development point of view, being able to run your application and make sure variables are being set correctly, files are being loaded from the correct locations and each individual step in a workflow has been called are all crucial. Normally, developers do this through debugging but Tracing is equally valid and valuable especially for retrospective analysis. However, having the ability to ignore these Traces, or simply not generate them in a production environment is also essential to prevent performance problems or producing so many records that it is impossible to see any issues.

From a production point of view, being able to quickly identify and diagnose exceptions or errors is also crucial. The Tracing framework should record every error that occurs, and ideally alert somebody to the issues. Similarly, some issues can be prevented by watching for thresholds being breeched or timeouts occurring.

TraceEventType and Trace Switches

To cater for the requirements above, the Trace framework supports different types of events and levels of severity that can be switched on or off through the TraceEventType enumeration. The current list of TraceEventType severity levels includes:

• Critical – records something that was unexpected and means the application is in an undetermined state or cannot continue
• Error – records something that was unexpected or failed but the application can continue to operate, such as a credit card payment failed
• Information – records general information such as a successful logon, a successful overnight process
• Verbose – typically used by developers when debugging and includes information such as a list of parameters that have been gathered, or a file path that is to be used
• Warning – records information that may become a problem such as a memory threshold has been breached or the amount of free disk space is getting low; the application can continue but may need looking at

The following shows an example of how some normal code could be instrumented, using several different levels. In this case:

Line 4 shows a developer message saying that we are about to store some data to the database

Line 9 is a developer message that says we have successfully saved the data to the database

Line 13 is an error message because an exception was thrown when saving the data. In this case, we could retry or compensate but the application can continue

Line 18 is a critical error from which the application cannot continue.

public void StoreData(object data)
{
  TraceSource traceSource = new TraceSource("DemoApp");
  traceSource.TraceEvent(TraceEventType.Verbose, 0, "About to store the passed in data");

  try
  {
    // Store the data in the database
    traceSource.TraceEvent(TraceEventType.Verbose, 0, "Data saved successfully");
  }
  catch (SqlException ex)
  {
    traceSource.TraceEvent(TraceEventType.Error, 1, "An error occurred contacting the database '{0}'", ex);
    throw;
  }
  catch (OutOfMemoryException ex)
  {
    traceSource.TraceEvent(TraceEventType.Critical, 2, "The application has run out of memory '{0}'", ex);
    throw;
  }
}

The Trace framework can be configured through Trace Switches so that the levels at which events are raised can have different outcomes. For example, it is possible to do nothing with Verbose events and just ignore them, write Warnings and Errors to the Event Log and send emails to support staff for Critical events. When the code is written, the developer should understand the different levels above and choose the most appropriate one as above. Then, configuration can be used to adjust the outcomes without changing the code.

The following shows a simple configuration where all trace information is dumped to the Console through a single Trace Switch.

Line 4 then shows a TraceSource being configured. We will talk about TraceSources in a moment but effectively this section says the any messages whose level is Verbose or above (effectively all levels) should be written to the following listeners – the console listener is then added.

Line 11 shows where the listeners are configured. In this case, there is only one listener which is the console.

The <trace autoflush=”true”/> ensures trace information is written immediately as opposed to when the application is closed.

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Verbose">
        <listeners>
          <add name="console"/>
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add name="console"
        type="System.Diagnostics.ConsoleTraceListener" />
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

Running the application with this configuration produces the following output for normal flow, i.e. no exceptions:

DemoApp Verbose: 0 : About to store the passed in data
DemoApp Verbose: 0 : Data saved successfully

If we wanted to prevent the developer information from being recorded, we could simply change the switchValue to Information. This would mean only Information messages or above are sent to the Trace Listeners and recorded. In the example code above, no output would now be generated unless an exception was thrown.

We can also add different listeners for different levels. The following example configuration shows that Information messages or above are displayed in the Console and Errors or above are added to the EventLog.

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Information">
        <listeners>
          <add name="console"/>
        </listeners>
      </source>
      <source name="DemoApp" switchValue="Error">
        <listeners>
          <add name="console"/>
          <add name="eventlog"/>
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add name="console"
        type="System.Diagnostics.ConsoleTraceListener" />
      <add name="eventlog"
        type="System.Diagnostics.EventLogTraceListener"
        initializeData="DemoAppEventLog" />
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

If we ran the code above and there was an error contacting the database, the following would be seen in the console:

DemoApp Error: 1 : An error occurred contacting the database 'An Exception ...'

The following would also be seen in the EventLog:

Trace Filters

Trace Filters have the same effect as Trace Switches in determining which Listeners record information. However, Trace Switches determine which listeners receive the event to be traced whereas Trace Filters are applied to the listener themselves and enable the listener to determine if it should Trace. This may seem very similar but it does make for simpler configuration.

If we take the above configuration and change it around slightly to use filters we can end up with exactly the same results. In this configuration, all messages (the Verbose Trace Switch is being used) are sent to the console and eventlog listeners but the console listener only records Information events or above and the eventlog only records Error events or above.

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Verbose">
        <listeners>
          <add name="console"/>
          <add name="eventlog"/>
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add
        type="System.Diagnostics.ConsoleTraceListener"
        name="console">
        <filter
          type="System.Diagnostics.EventTypeFilter"
          initializeData="Information"/>
      </add>
      <add name="eventlog"
        type="System.Diagnostics.EventLogTraceListener"
        initializeData="DemoAppEventLog">
        <filter
          type="System.Diagnostics.EventTypeFilter"
          initializeData="Error"/>
      </add>
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

Trace Filters prove invaluable in some scenarios such as when numerous Trace Sources are configured. It becomes trivial to have one Trace Listener handle all errors produced by all Trace Sources.

Trace Sources

The initial version of the Trace framework used simple Write calls to log information. The new version uses a Trace Source instead. To ensure you are using the latest version of the Trace framework:

Do not use Write, use the TraceSource class!

A Trace Source is really a way of being able to group code and to manage the Trace levels associated with it; the Trace Switches and Filters. In the examples above, we have been using a Trace Source called “DemoApp”. The code traces events against the “DemoApp” Trace Source and the configuration specifies a switchValue and one or more listeners. This means that all code that traces against the “DemoApp” TraceSource class instance will be subject to the same switchValue, filters and listeners.

Normally the TraceSource name is the same as the assembly. For example, a database access assembly may be required to trace all errors to the Event Log whereas the UI assembly may only trace critical events to a file. We can configure the two assemblies differently if they use different Trace Source names. Microsoft follows this rule. If you wanted to trace low level information from the Microsoft networking layer, you could add the following to your configuration file and see all levels of message recorded in the XmlWriterTraceListener:

<system.diagnostics>
  <sources>
    <source name="System.Net" maxdatasize="1024">
      <listeners>
        <add name="xml" />
      </listeners>
    </source>
    <source name="System.Net.Sockets">
      <listeners>
        <add name="xml" />
      </listeners>
    </source>
    <source name="System.Net.Cache">
      <listeners>
        <add name="xml" />
      </listeners>
    </source>
  </sources>
  <switches>
    <add name="System.Net" value="Verbose"/>
    <add name="System.Net.Sockets" value="Verbose"/>
    <add name="System.Net.Cache" value="Verbose"/>
  </switches>
  <sharedListeners>
    <add initializeData="C:\logs\web.svclog"
      type="System.Diagnostics.XmlWriterTraceListener"
      name="xml" />
  </sharedListeners>
  <trace autoflush="true">
  </trace>
</system.diagnostics>

In Conclusion

Hopefully, this posting has given you a good background in why the System.Diagnostics.Trace framework should be the only trace framework you need, given you some idea of how to get started, configure the output levels, switches and filters and use the Trace code.

The following postings will look at:

More detailed configuration and usage of the framework

How to propagate and gather information across process and machine boundaries

How to pass ActivityIds to ASP.NET/MVC applications for end-to-end tracing in REST

A couple of helper classes that will prove useful when using the Trace framework

P.N.