Microsoft Enterprise Library : Non-Formatted Trace Listeners (part 3) - Adding Additional Context Information, Tracing and Correlating Activities

6. Adding Additional Context Information

While it's useful to have every conceivable item of information included in your log messages, it's not always the best approach. Collecting information from the environment absorbs processing cycles and increases the load that logging places on your application. The Logging block is highly optimized to minimize the load that logging incurs. As an example, some of the less useful information is not included in the log messages by default—particularly information that does require additional resources to collect.

However, you can collect this information if you wish. You may decide to do so in special debugging instrumentation that you only turn on when investigating problems, or for specific areas of your code where you need the additional information, such as security context details for a particularly sensitive process.

After checking that a log entry will not be blocked by filters, the ShowDetailsAndAddExtraInfo method (shown in the previous section) adds a range of additional context and custom information to the log entry. It uses the four standard Logging block helper classes that can generate additional context information and add it to a Dictionary. These helper classes are:

• The DebugInformationProvider, which adds the current stack trace to the Dictionary.

• The ManagedSecurityContextInformationProvider, which adds the current identity name, authorization type, and authorization status to the Dictionary.

• The UnmanagedSecurityContextInformationProvider, which adds the current user name and process account name to the Dictionary.

• The ComPlusInformationProvider, which adds the current activity ID, application ID, transaction ID (if any), direct caller account name, and original caller account name to the Dictionary.

The following code shows how you can use these helper classes to create additional information for a log entry. It also demonstrates how you can add custom information to the log entry—in this case by reading the contents of the application configuration file into the Dictionary. After populating the Dictionary, you simply set it as the value of the ExtendedProperties property of the log entry before writing that log entry.

...
// Create additional context information to add to the LogEntry.
Dictionary<string, object> dict = new Dictionary<string, object>();
// Use the information helper classes to get information about
// the environment and add it to the dictionary.
DebugInformationProvider debugHelper = new DebugInformationProvider();
debugHelper.PopulateDictionary(dict);
ManagedSecurityContextInformationProvider infoHelper
    = new ManagedSecurityContextInformationProvider();
infoHelper.PopulateDictionary(dict);
UnmanagedSecurityContextInformationProvider secHelper
    = new UnmanagedSecurityContextInformationProvider();
secHelper.PopulateDictionary(dict);
ComPlusInformationProvider comHelper = new ComPlusInformationProvider();
comHelper.PopulateDictionary(dict);
// Get any other information you require and add it to the dictionary.
string configInfo = File.ReadAllText(@"..\..\App.config");
dict.Add("Config information", configInfo);
// Set dictionary in the LogEntry and write it using the default LogWriter.
entry.ExtendedProperties = dict;
defaultWriter.Write(entry);
....

					  

The example produces the following output on screen.

Added the current stack trace to the Log Entry.
Added current identity name, authentication type, and status to the Log Entry.
Added the current user name and process account name to the Log Entry.
Added COM+ IDs and caller account information to the Log Entry.
Added information about the configuration of the application to the Log Entry.
LogEntry written to configured trace listeners.

					  

To see the additional information added to the log entry, open Windows Event Viewer and locate the new log entry. We haven't shown the contents of this log entry here as it runs to more than 350 lines and contains just about all of the information about an event occurring in your application that you could possibly require!

7. Tracing and Correlating Activities

One of the problems with logging is that relying simply on the event ID to correlate multiple events that are related to a specific process or section of code is difficult and error prone. Event IDs are often not unique, and there can be many events with the same event ID generated from different instances of the components in your application that are intermixed in the logs.

The Logging block makes it easy to add an additional unique identifier to specific log entries that you can later use to filter the log and locate only entries related to a specific process or task. The Logging block tracing feature makes use of the .NET Correlation Manager class, which maintains an Activity ID that is a GUID. By default, this is not set, but the Logging block allows you to use a TraceManager to generate Tracer instances. Each of these sets the Activity ID to a randomly generated GUID value that is maintained only during the context of the tracer. The Activity ID returns to its previous value when the tracer is disposed or goes out of scope.

You specify an operation name when you create the tracer. This is effectively the name of a category defined in the configuration of the block. All log entries created within the context of the tracer will be assigned to that category in addition to any categories you specify when you create the log entry.

You can specify a GUID value when you create and start a tracer, and all subsequent log entries within the scope of that tracer and all nested tracers that do not specify a different GUID will have the specified activity ID. If you start a new nested tracer instance within the scope of a previous one, it will have the same activity ID as the parent tracer unless you specify a different one when you create and start the nested tracer; in that case, this new activity ID will be used in subsequent log entries within the scope of this tracer.

---

Note:

Although the Logging block automatically adds the activity ID to each log entry, this does not appear in the resulting message when you use the text formatter with the default template. To include the activity ID in the logged message that uses a text formatter, you must edit the template property in the configuration tools to include the token {property(ActivityId)}. Note that property names are case-sensitive in the template definition.

---

7.1. An Example of Tracing Activities

The example, Tracing activities and publishing activity information to categories, should help to make this clear. At the start of the application, the code resolves a TraceManager instance from the Enterprise Library container in the same way as we resolved the Log-Writer we've been using so far.

// Resolve a TraceManager object from the container.
TraceManager traceMgr
    = EnterpriseLibraryContainer.Current.GetInstance<TraceManager>();

Next, the code creates and starts a new Tracer instance using the StartTrace method of the TraceManager, specifying the category named General. As it does not specify an Activity ID value, the TraceManager creates one automatically. This is the preferred approach, because each separate process running an instance of this code will generate a different GUID value. This means you can isolate individual events for each process.

The code then creates and writes a log entry within the context of this tracer, specifying that it belongs to the DiskFiles category in addition to the General category defined by the tracer. Next, it creates a nested Tracer instance that specifies the category named Database, and writes another log entry that itself specifies the category named Important. This log entry will therefore belong to the General, Database, and Important categories. Then, after the Database tracer goes out of scope, the code creates a new Tracer that again specifies the Database category, but this time it also specifies the Activity ID to use in the context of this new tracer. Finally, it writes another log entry within the context of the new Database tracer scope.

// Start tracing for category 'General'. All log entries within trace context
// will be included in this category and use any specified Activity ID (GUID).
// If you do not specify an Activity ID, the TraceManager will create a new one.
using (traceMgr.StartTrace("General"))
{
  // Write a log entry with another category, will be assigned to both.
  defaultWriter.Write("LogEntry with category 'DiskFiles' created within "
         + "context of 'General' category tracer.", "DiskFiles");
  // Start tracing for category 'Database' within context of 'General' tracer.
  // Do not specify a GUID to use so that the existing one is used.
  using (traceMgr.StartTrace("Database"))
  {
    // Write a log entry with another category, will be assigned to all three.
    defaultWriter.Write("LogEntry with category 'Important' created within "
       + "context of first nested 'Database' category tracer.", "Important");
  }
  // Back in context of 'General' tracer here.
  // Start tracing for category 'Database' within context of 'General' tracer
  // as above, but this time specify a GUID to use.
  using (traceMgr.StartTrace("Database",
                  new Guid("{12345678-1234-1234-1234-123456789ABC}")))
  {
    // Write a log entry with another category, will be assigned to all three.
    defaultWriter.Write("LogEntry with category 'Important' created within "
           + "context of nested 'Database' category tracer.", "Important");
  }
  // Back in context of 'General' tracer here.
}

					  

Not shown above are the lines of code that, at each stage, write the current Activity ID to the screen. The output generated by the example is shown here. You can see that, initially, there is no Activity ID. The first tracer instance then sets the Activity ID to a random value (you will get a different value if you run the example yourself), which is also applied to the nested tracer.

However, the second tracer for the Database category changes the Activity ID to the value we specified in the StartTrace method. When this tracer goes out of scope, the Activity ID is reset to that for the parent tracer. When all tracers go out of scope, the Activity ID is reset to the original (empty) value.

- Current Activity ID is: 00000000-0000-0000-0000-000000000000
Written LogEntry with category 'DiskFiles' created within context of 'General'
 category tracer.
- Current Activity ID is: a246ada3-e4d5-404a-bc28-4146a190731d
Written LogEntry with category 'Important' created within context of first
 'Database' category tracer nested within 'DiskFiles' category TraceManager.
- Current Activity ID is: a246ada3-e4d5-404a-bc28-4146a190731d
Leaving the context of the first Database tracer
- Current Activity ID is: a246ada3-e4d5-404a-bc28-4146a190731d
Written LogEntry with category 'Important' created within context of second
 'Database' category tracer nested within 'DiskFiles' category TraceManager.
- Current Activity ID is: 12345678-1234-1234-1234-123456789abc
Leaving the context of the second Database tracer
- Current Activity ID is: a246ada3-e4d5-404a-bc28-4146a190731d
Leaving the context of the General tracer
- Current Activity ID is: 00000000-0000-0000-0000-000000000000
Open the log files in the folder C:\Temp to see the results.

					  

If you open the RollingFlatFile.log file you will see the two log entries generated within the context of the nested tracers. These belong to the categories Important, Database, and General. You will also see the Activity ID for each one, and can confirm that it is different for these two entries. For example, this is the first part of the log message for the second nested tracer, which specifies the Activity ID GUID in the StartTrace method.

Timestamp: 01/12/2009 12:12:00
Message: LogEntry with category 'Important' created within context of second
nested 'Database' category tracer.
Category: Important, Database, General
Priority: -1
EventId: 1
Severity: Information
Title:
Activity ID: 12345678-1234-1234-1234-123456789abc

					  

---

Note:

Be aware that other software and services may use the Activity ID of the Correlation Manager to provide information and monitoring facilities. An example is Windows Communication Foundation (WCF), which uses the Activity ID to implement tracing.

You must also ensure that you correctly dispose Tracer instances. If you do not take advantage of the using construct to automatically dispose instances, you must ensure that you dispose nested instances in the reverse order you created them—by disposing the child instance before you dispose the parent instance. You must also ensure that you dispose Tracer instances on the same thread that created them.