Tracing Activities and Propagating Context Information

In some cases, you will need to log information at the start and end of a particular activity, including timing information. In addition, you can trace the progress of the activity at selected points in the application. Tracing allows you to associate all events between the start and end of an activity with an ActivityID property and a category. The ActivityID property allows you to correlate log entries that are written during the execution of an activity. You can use filters and categories to direct and control the information produced for an event that can occur in the context of any activity.

Typical Goals

In this scenario, the goal is to log the beginning and end of an activity to a common category. The configuration settings for the category determine the destination of the log entries.

Solution

Configure the application to use the Logging Application Block, specifying the category to be used when tracing activity start and end times. Use the StartTrace method of the TraceManager class (which creates an instance of the Tracer class) where you want the timed event to begin, specifying a configured category. When the Tracer instance is created, the activity start time will be logged using the specified category. The following code assumes you have retrieved a reference to an instance of the TraceManager class and stored it in a variable named traceMgr.

using (traceMgr.StartTrace("Log Category"))
{
  // Perform processing to be timed here
}

'Usage
Using traceMgr.StartTrace("Log Category")
  ' Perform processing to be timed here
End Using

The end time of the activity is logged using the same category when the Tracer object returned from the StartTrace method is disposed. The automatic disposal behavior of the using statement causes the end time to be logged when the scope of the using statement ends.

Note

The non-static facade named TraceManager replaces the direct instantiation of the static Tracer class approach that was the default in earlier versions of Enterprise Library. For information about the previous approach, see the online documentation for Enterprise Library 4.1, available on the MSDN Web Site.

Specifying and Displaying the Activity ID

By default, the StartTrace method will generate a unique identifier for the activity as a Guid. You can use this activity identifier to correlate all log entries for particular execution of an activity.

using (traceMgr.StartTrace("General"))
{
  ...
}

'Usage
Using traceMgr.StartTrace("General")
  ...
End Using

Alternatively, you can specify the activity identifier in the call to the StartTrace method, as shown here. However, this prevents the block from generating a different activity identifier for each executing instance of the code. You will generally only use this approach if you want to apply some particular application-specific activity identifier.

using (traceMgr.StartTrace("General", new Guid("{12345678-1234-1234-1234-123456789ABC}")))
{
  ...
}

'Usage
Using traceMgr.StartTrace("General", New Guid("{12345678-1234-1234-1234-123456789ABC}"))
  ...
End Using

The application block uses the .NET Framework CorrelationManager class to maintain the activity identifier. It automatically adds the activity ID to each log entry, but 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, 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.

Propagation of Context Information

Categories determine the destinations for the log entries and are used for filtering. The categories associated with a Tracer object remain in effect as long as that Tracer object remains in scope. This means that the categories specified in the StartTrace method call are included in the list of categories for any call to the LogWriter.Write method while that Tracer object is in scope. In the following code, the message written in the call to the LogWriter.Write method belongs to both the UI Events category and the Debug category. The example assumes you have resolved an instance of the LogWriter class through the container and saved it in a variable named myLogWriter and resolved an instance of the TraceManager class and stored it in a variable named traceMgr.

using (traceMgr.StartTrace("UI Events"))
{
  // The following message will be associated with the 
  // "UI Events" and "Debug" categories.
  myLogWriter.Write("My message", "Debug");
}

'Usage
Using traceMgr.StartTrace("UI Events")
  ' The following message will be associated with the  
  ' "UI Events" and "Debug" categories.
  myLogWriter.Write("My message", "Debug")
End Using

By using the Logging Application Block, developers can trace the progress of an activity through a series of method calls. You can create log entries that have a common activity identifier by instantiating nested Tracer objects that do not specify an activity identifier. The nested Tracer objects will create log entries with the same activity identifier of the parent Tracer object currently in scope, as shown in the following code.

using (traceMgr.StartTrace("A"))
{
  // Log entries created here will belong to category "A".
  ...
  using (traceMgr.StartTrace("B"))
  {
    // Log entries created here will belongs to both category "A" and category "B".
    ...    
  }
}

'Usage
Using traceMgr.StartTrace("A")
  ' Log entries created here will belong to category "A".
  ...
  Using traceMgr.StartTrace("B")
    ' Log entries created here will belongs to both category "A" and category "B".
    ...    
  End Using
End Using

LogEntry instances created within the scope of a nested Tracer object belong to the category specified for the nested Tracer object as well as to all categories for parent Tracer objects. All log entries for this activity have the same activity identifier. In the following example, the LogEntry object is associated with the categories UI Events, Data Access Events, and Troubleshooting. The example assumes you have resolved an instance of the LogWriter class through the container and saved it in a variable named myLogWriter and resolved an instance of the TraceManager class and stored it in a variable named traceMgr.

using (traceMgr.StartTrace("UI Events"))
{
  using (traceMgr.StartTrace("Data Access Events"))
  {
    LogEntry logEntry = new LogEntry();
    logEntry.Categories.Add("Troubleshooting");
    myLogWriter.Write(logEntry);
  }
}

'Usage
Using traceMgr.StartTrace("UI Events")
  Using traceMgr.StartTrace("Data Access Events")
    Dim logEntry As New LogEntry()
    logEntry.Categories.Add("Troubleshooting")
    myLogWriter.Write(logEntry)
  End Using
End Using

For information about resolving Enterprise Library objects in your applications, see Creating and Referencing Enterprise Library Objects.

Usage Notes

The TraceManager.StartTrace method creates and returns a reference to a Tracer instance that performs the trace function. Multiple Tracer objects may exist at one time. However, they must be disposed in the reverse order in which they were created. The recommended approach is to use a using statement (Using in Visual Basic). This causes your Tracer objects to be disposed in the correct order.

If you explicitly dispose your Tracer objects, dispose them in reverse order than they were created. The following scenario is not supported.

Tracer tracer1 = traceMgr.StartTrace("Category1");
Tracer tracer2 = traceMgr.StartTrace("Category2");

// INCORRECT: Should dispose tracer2 before tracer1.
tracer1.Dispose(); 
tracer2.Dispose();

'Usage
Dim tracer1 As Tracer = traceMgr.StartTrace("Category1")
Dim tracer2 As Tracer = traceMgr.StartTrace("Category2")

' INCORRECT: Should dispose tracer2 before tracer1.
tracer1.Dispose() 
tracer2.Dispose()