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

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