MongoDB for Node.js Developers

A few months ago I took part in an online MongoDB course – M102: MongoDB for DBAs. It was presented by Dwight Merriman, one of the original authors of MongoDB. It was a great course, taking a few weeks to complete but providing a really good overview of MongoDB, its features and capabilities. If you are new to MongoDB, or just want to know what all the hype is about, I would recommend this course.

There is a new course starting on 12th August – M101JS: MongoDB for Node.js Developers (https://education.10gen.com/courses/10gen/M101JS/2013_August/about). If you want to know how to write amazingly flexible, rapid applications then look no further than this dynamic duo! I think this is going to be a brilliant course so make sure you reserve your place soon.

RS

.NET Trace, The Only Logging Framework You’ll Ever Need – Helper Classes

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.

.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.

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

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.

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

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.