.NET Trace, The Only Logging Framework You’ll Ever Need – Part 4

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.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s