Getting started with the Logging Application Block

• LoggingBlockInvestigator demo project - 12.3 Kb

Note: You will need to follow the steps in Setting Up Your Environment before the project will build.

I have completed a major re-write of this article using the Enterprise Library rather than the EIF and the stand-alone Logging Application Block. This is available at Get Logging with the Enterprise Library.

Contents

• Introduction
• Background
• The Basics
• Linking the Basics Together
• Setting Up Your Environment
• Instrumenting an Application
• The Future
• Conclusion
• Revision History

Introduction

Have you ever encountered a system where the logging is a twisted pile of spaghetti? One where it seems to save trace messages to five different files? Or it requires seven different flags in the registry to control its output?

All too often, logging is added to a system in an ad-hoc, as the need arises, manner. When this approach is applied to a large system with many sub-systems and layers, it can lead to numerous “home grown” logging mechanisms being implemented; each implementation having its own configuration peculiarities and probably logging in different ways (e.g., one subsystem to the Windows Event Log, one to a file in the root directory, one to a database etc.). This article will introduce you to the Microsoft Logging Application Block, and show how it could bring some consistency to an application’s logging.

This article is for those who have never encountered the Logging Application Block, those who are looking to evaluate it, and those who have looked at it and thought it seemed like too much trouble. I will provide an overview of what features the Logging Application Block provides, followed by a description of how to get the basics working in your environment.

The article will not explore too deeply the additional features the Logging Application Block provides over the Microsoft Enterprise Instrumentation Framework (EIF).

Background

Many applications, and especially large-scale systems, could benefit from a consistent approach to logging. To help, there are a number of logging libraries available to the .NET developer, such as Log4Net and NSpring. As of April 2003, there has been another alternative, the Microsoft Enterprise Instrumentation Framework (EIF).

The EIF provides a simple way for your code to raise “Events” in a consistent manner across your managed application. A powerful configuration file allows the routing of those Events to be determined at run time (rather than at compile time). The routing to one or more “Event Sinks” can be based on a combination of the type of the Event and the source of the Event. The configuration file also allows you to specify that only certain elements of your application, or particular processes within it, produce logging.

As part of Microsoft’s Patterns & Practices initiative, the Logging Application Block has been released. This application block extends the EIF with three new Event Sinks:

• Microsoft Message Queuing (MSMQ)
• SQL Server Basic
• SQL Server Flexible

It also provides new versions of the Windows Event Log and Windows Management Instrumentation (WMI) Event Sinks, adding facilities such as Log Level. Another new feature is Event Transformation, which allows you to change the contents of an Event before it is stored. For instance, transformations could remove sensitive information or add additional data. By integrating with the Web Services Enhancements (WSE), the Logging Application Block allows log tracing to continue across web service boundaries.

When I first looked at the Logging Application Block, I nearly dismissed it as too much effort. I’m glad I persisted.

The Basics

The EIF, and hence the Logging Application Block, make use of three basic concepts to provide a logging framework: Events, Event Sources and Event Sinks.

Events

An Event is the object that you “raise” when your application needs to log some information. For instance, adding the following to your application would raise an Event of type TraceMessageEvent:

TraceMessageEvent.Raise("Hello World");

It is as simple as that. OK, you do have to put in some using statements and your project must reference the EIF... but the code can be as basic as that!

The EIF defines a number of Events, such as:

• TraceMessageEvent
• ErrorEvent
• AdminMessageEvent
• AuditMessageEvent

These all contain a number of “Fields” that are automatically populated with details of the system at the time the Event was raised (e.g., machine name, timestamp, application domain name, etc.). Through the configuration file, it is possible to request that additional Fields be populated. For example, COM+ properties (including Fields such as the current Transaction ID) or security information can be added to the Event’s contents.

Each Event type also adds its own specific Fields. For example, the ErrorEvent allows a Severity Field to be set.

The Logging Application Block includes new versions of some of the EIF Events. These provide new Fields and some new functionality (e.g., Log Level). It also adds some completely new Events such as the MeteringEvent for web services.

Event Sources

An Event Source allows you to indicate where an Event was raised from. All Events are raised from an Event Source. If the developer doesn’t specify an Event Source explicitly, a default source is used. The code shown above does not explicitly set the source, therefore, the default “Application” source is used. The code below explicitly defines the source of an Event:

EventSource theBusinessLayerSource = new EventSource("Business Layer");
TraceMessageEvent.Raise(theBusinessLayerSource, "Hello World Again");

The EventSource class is known as a “Software Element Event Source”. These Event Sources indicate that a particular section of the software is raising an event. They can be used to partition your application however makes sense to you. You might use one for your configuration classes, one for your data access layer, or even a distinct one for every class in your system.

There is a second type of Event Source, the “Request Event Source”. This type is used to indicate that an Event is being raised as part of a particular process (or execution path through the application). For instance, you might use it to indicate that an Event has been raised as part of a "Create New Customer" process:

RequestEventSource createCustomerSource = 
   new RequestEventSource("Create New Customer");
using (RequestTrace request = new RequestTrace(createCustomerSource)
{
   TraceMessageEvent.Raise("Hello World Once More");
}

The RequestEventSource is wrapped in a RequestTrace. The using statement ensures the RequestTrace is terminated correctly. All Events raised between the using statement’s opening and closing brackets will be tagged as coming from the “Create New Customer” Request Event Source. That includes Events raised in other methods, classes, or even assemblies (provided they use the EIF). Request Event Sources can be nested, the event will be tagged with both the inner most Event Source and the root Event Source.

Software Element Event Sources and Request Event Sources can be used together, i.e., the above could be changed to:

using (RequestTrace request = new RequestTrace(createCustomerSource)
{
   TraceMessageEvent.Raise(theBusinessLayerSource, "Hello World One Last Time");
}

This would result in an Event tagged with both the “Business Layer” and the “Create New Customer” Event Sources.

One warning about the above examples, creating an Event Source can be slow. Therefore, it is recommended that you create each Event Source only once and hold it in a static reference to be reused.

The Logging Application Block improves the functionality of the Request Event Source. It allows the RequestTrace to work across calls to web services!

Event Sinks

Whilst Events originate from Event Sources, they terminate at Event Sinks. An Event Sink receives Events and is responsible for persisting them. The EIF provides three Event Sinks:

• TraceEventSink – writes to a Windows Event Trace log file.
• LogEventSink – writes to the Windows Event Log.
• WMIEventSink – outputs to the WMI.

As mentioned in the Background section of this article, the Logging Application Block modifies the latter two and adds three more Event Sinks. You can always write your own custom Event Sink as well.

Viewing the logged events requires a reader for each particular data store. The Event Viewer can be used for the Windows Event Log. A sample C# project, TraceViewer, is provided with the EIF to open Windows Event Trace log files. The WMI events can be seen through a WMI Event Viewer.

Linking the Basics Together

Hopefully, the section above gives you an insight into the features provided by the EIF and the Logging Application Block. What that section doesn’t describe is how Event, Event Source and Event Sink objects are made to interact with each other. That “plumbing” is provided by the EIF based on settings in a configuration file.

There are three more concepts to understand: Event Categories, Filters and Filter Bindings. These are not defined at compile time, but at run time, when the EIF reads the configuration file. Therefore, if you need a new Event Category, you can simply change a configuration file. It is this flexibility that makes the EIF so powerful.

Event Categories

Events can be grouped together into Event Categories. By creating categories, you will be able to independently turn logging on or off for particular groups of Events.

Often, one category you will create is an “All Events” category. You may want another category containing only audit events, another that contains trace messages, etc. Note that an event can be a member of more than one category.

For instance:

<eventCategory name="All Events" 
          description="A category that contains all events.">
   <event type="System.Object" />
</eventCategory>

This fragment defines an Event Category called "All Events". It indicates that all Events of type System.Object, or Events derived from System.Object, should be members of this category. Since every class is derived from System.Object, this category automatically includes all Events.

Filters

A Filter determines which Event Categories are routed to which Event Sinks. For instance, you may want to have all trace messages sent to the TraceEventSink and all audit messages sent to both the TraceEventSink and the LogEventSink.

To implement this, you would first create two Event Categories, one containing the trace events (see “Trace Events” below) and one containing the audit events (see “Audit Events” below). Secondly, you would create a Filter which specified that events from “Trace Events” category should be directed to the TraceEventSink (traceSink) and that events from “Audit Events” category should be sent to both the TraceEventSink and the LogEventSink (logSink). This is shown below:

<eventCategories>

 <eventCategory name="Trace Events">
   <event type="Microsoft.ApplicationBlocks.Logging.Schema.TraceMessageEvent, 
                                                                        ... " />
 </eventCategory>
   
 <eventCategory name="Audit Events">
   <event type="Microsoft.ApplicationBlocks.Logging.Schema.AuditMessageEvent, 
                                                                        ... " />
 </eventCategory> 
      
</eventCategories>

<filters>
   <filter name="filterTraceAndAuditDifferently">
   
      <eventCategoryRef name="Trace Events">
         <eventSinkRef name="traceSink"/>
      </eventCategoryRef>
      
      <eventCategoryRef name="Audit Events">
         <eventSinkRef name="traceSink"/>
         <eventSinkRef name="logSink"/>
      </eventCategoryRef>
      
   </filter>
</filters>

Filter Bindings

A Filter Binding links an Event Source to one or more Filters. This allows you to route Events raised by different parts of your system to different Filters.

For instance, if you are having a problem with a single process in your system, you could create a single Filter Binding between the Request Event Source that wraps that process and a Filter that directs Events in the “All Events” Event Category to the TraceEventSink. All other Events would be ignored. For example:

<eventSources>
   <eventSource name="Create New Customer" type="request"/>
</eventSources>

<filters>
   <filter name="Trace All">
      <eventCategoryRef name="All Events">
         <eventSinkRef name="traceSink"/>
      </eventCategoryRef>
   </filter>
</filters>

<filterBindings>
   <eventSourceRef name="Create New Customer">
      <filterRef name="Trace All" />
   </eventSourceRef>
</filterBindings>

This fragment will ensure that all events raised as part of the "Create New Customer" process are sent to the traceSink.

Setting Up Your Environment

First off, your system must at least meet the following requirements:

• Windows 2000 Service Pack 2 (SP3 preferably), Windows Server 2003 or Windows XP.
• .NET Framework 1.1.
• Visual Studio .NET 2003 Enterprise Architect, Enterprise Developer, or .NET Professional edition.

Here are the steps I followed to create a development environment:

• Install the EIF. This is now generally available from here;
• Turn on a trace session by editing the file [EIF]\Bin\Trace Service\TraceSessions.config (where [EIF] is the install directory of the EIF) and changing the enabled attribute’s value to “true” for the session element. Note, this configuration file allows you to specify which file the Windows Event Trace Log writes to;
• Install Web Services Enhancements 2.0, available from here. I chose the Visual Studio Developer option;
• Run the self extracting ZIP file containing the Logging Application Block, available from here;
• Install the Logging Application Block by running the extracted Logging.msi file;
• Follow the instructions in the “Building the Logging Block” section of the extracted Logging.pdf file. These guide you through building and installing the block.

Some notes on this:

• This process looks tedious, but is simple and worth;
• The “Visual Studio command prompt” should be available from your Start menu;
• I did find that a reference in the MeteringOutputFilter and RequestTracingFilter projects to Microsoft.Web.Services had to be changed to Microsoft.Web.Services2 (with corresponding changes to the using directives in some source files);
• Changing the configuration files of the samples may not be necessary if you are not going to build them, but it is simple using Visual Studio’s “Replace in Files” function.

Instrumenting an Application

Perhaps the best way to get to grips with the Logging Application Block is to try it. The download for this article contains the code for a sample Windows Forms application (LoggingBlockInvestigator.exe) that should allow you to experiment. You will need to edit its EnterpriseInstrumentation.config file to replace the PublicKeyToken attributes with the value identified when you were building the Logging Application Block (perform a Search and Replace of the string 25ffac55882d4eb6).

Raising Events

The LoggingBlockInvestigator.exe application raises two audit events in the Main method, one on start up and one on shutdown:

AuditMessageEvent auditEvent = new AuditMessageEvent();
auditEvent.Message = "Starting the application";
EventSource.Application.Raise(auditEvent);

Application.Run(new MainForm());

AuditMessageEvent.Raise("Shutting down the application");

This code shows two techniques for raising events from the default “Application” Event Source. The first technique explicitly creates an Event object and initializes it with a message. The second, more compact technique, creates the Event implicitly.

If you build and run the LoggingBlockInvestigator.exe application, then close it down, you will find two new entries in your Windows Event Log, in the Application section. If you look at the details, you will see an XML document containing the appropriate messages.

With the EIF, Microsoft provides a simple trace log viewer. If you run [EIF]\Samples\Trace Viewer\TraceViewer.exe and open the TraceLog.Log file, you should see the two events listed there as well.

Creating Event Sources

By default, all messages are marked as raised by the “Application” Event Source. The code in the sample application for the “Log From My Source” button handler uses an explicit source instead:

private static EventSource eventSource = new EventSource("My Source");
private void LogFromMySource_Click(object sender, System.EventArgs e)
{
   TraceMessageEvent.Raise(eventSource, "Traced from my source");
}

Run the sample application and press the “Log From My Source” button, then open the TraceLog.Log file in TraceViewer.exe. The last entry should be a trace message. Looking at the details will show that the EventSourceName is set to "My Source".

The code above is using a Software Element Event Source. The code behind the “Log With Request Trace” button uses two nested Request Event Sources:

private RequestEventSource requestEventSource1 = 
           new RequestEventSource("My Request Source For Tracing");
private RequestEventSource requestEventSource2 = 
           new RequestEventSource("My Nested Request Source For Tracing");
private void LogWithRequestTrace_Click(object sender, System.EventArgs e)
{
   using (RequestTrace request = new RequestTrace(requestEventSource1))
   {
      TraceMessageEvent.Raise(eventSource, "My first request");

      using (RequestTrace requestNested = new RequestTrace(requestEventSource2))
      {
         TraceMessageEvent.Raise("My second request");
      }
   }
}

If you press the “Log With Request Trace” button, the following Events are saved into the TraceLog.Log file:

• TraceRequestStartEvent – indicating “My Request Source For Tracing” has started;
• TraceMessageEvent – the “My first request”;
• TraceMessageEvent – a repeat of the “My first request” because we gave this event both a Software Element and a Request Event Source, both of which are configured to route Events to the TraceLogSink;
• TraceNestedRequestStartEvent – indicating “My Nested Request Source For Tracing” has started. The details indicate that the RootRequestName is “My Request Source For Tracing”;
• TraceMessageEvent – the “My second request” Event, which is saved only once as it is not assigned a Software Element Event Source;
• TraceNestedRequestEndEvent – indicates the nested request has completed. The details give the execution time;
• TraceRequestEndEvent – indicates the outer request has completed.

Creating a Custom Event Sink

As well as using the provided Event Sinks, you can create your own. CustomEventSink.cs in the sample application shows how simple this is. The class is derived from Microsoft.EnterpriseInstrumentation.EventSinks.EventSink and the Write method is overridden. Put a break point in the Write method, then press the “Log To My Sink” button. Your break point should be hit, allowing you to explore the eventToRaise object.

Log Levels

A new feature introduced by the Logging Application Block is Log Levels. The ApplicationLogLevel indicates which Events should be published. In the sample application, this is set in the App.config file to “debug”. If you change this value to “error”, only the “Audit At Error Level” button will cause any new messages to be recorded in the Windows Event Log. The two audit Events raised in the Main method are ignored.

If you don’t explicitly set the Log Level for an Event, it defaults to “debug”. The following code, from behind the “Audit At Error Level” button, shows how to raise the Log Level:

AuditMessageEvent auditErrorEvent = new AuditMessageEvent();
auditErrorEvent.Message = "Logged at error level";
auditErrorEvent.EventPublishLogLevel = (int)LogLevel.Error;
EventSource.Application.Raise(auditErrorEvent);

It should be noted that the Logging Application Block has not changed the functionality of the TraceEventSink, so it still logs all Events routed to it, regardless of Log Level.

Configuration

The last few sections have introduced the code that you can add to your application to start logging through the Logging Application Block. There is one more very important task... configuration. Without configuring the EIF, your Events will never reach an Event Sink.

The EnterpriseInstrumentation.config file details how Events, Event Sources and Event Sinks are linked. A skeleton of this file can be generated for you. You must ensure your project references the System.Configuration.Install assembly and that it contains a class definition similar to this:

[RunInstaller(true)]
public class LoggingBlockInvestigatorInstaller : ProjectInstaller {};

Then, from the command line, run:

installutil MyApplication.exe

This will generate a functioning EnterpriseInstrumentation.config file, pre-populated with all the Events, Event Sources and Event Sinks that could be found in your application and its referenced assemblies. It will also contain some default Categories, Filters and Filter Bindings. You can then experiment with creating new Categories, Filters and Filter bindings.

If you look at the sample application’s EnterpriseInstrumentation.config file, you will see that it makes use of an EventSourceParameter on one of the Event Sources:

<eventSource name="My Source With Debug Info" ... >
   <eventSourceParameter name="PopulateDebugInfo" value="true" />
</eventSource>

The PopulateDebugInfo parameter is used to indicate that any Event being raised from the “My Source With Debug Info” Event Source should populate its debug information fields. If you run the sample application and press the “Log With Debug Information” button, the last entry in the TraceLog.Log file will have its StackTrace Field populated. Other pre-defined EventSourceParameters include:

• PopulateComPlusInfo - COM+ context information is populated;
• PopulateManagedSecurityInfo - .NET security context information is populated;
• PopulateWindowsSecurityInfo - Windows security context information is populated.

Also, in the file, you will see the Custom Event Sink declared as follows:

<eventSink name="customEventSink" ... >
   <parameter name="MyParam" value="My own parameter" />
</eventSink>

The “MyParam” parameter is passed to the Event Sink’s constructor. If you remove it, you’ll find that the CustomEventSink throws an exception as it has been coded to expect the parameter. This exception is caught by the EIF and logged to the Windows Event Log. Note: whether the exception is logged or not is controlled by the internalExceptionHandler attribute on the declaration of the Event Source in the configuration file.

Event Sink parameters can be used for whatever you like. The Event Sinks provided with the EIF and the Logging Application Block use them for such things as:

• Specifying which machine’s Windows Event Log should be written to;
• The name of the trace session to use when writing to the TraceEventSink (this is the name configured in the TraceSessions.config file).

The Future

What about the future? Microsoft in partnership with Avanade have been developing the next evolution of the Patterns & Practices Application Blocks. Enterprise Library is due for general release sometime early in 2005. This library will bring together a number of the existing Application Blocks, including Logging.

You can find more information about the new library at GotDotNet. Looking at the documentation currently available, any experience you gain with the current Logging Application Block will make understanding the new library simpler. However, there will not be a simple upgrade path. Some of the new features include:

• New sinks such as the EmailSink;
• Configuration via Enterprise Library Configuration Console;
• No longer dependent on the EIF.

Update: The Enterprise Library is now available.

Conclusion

Hopefully, this article provides a good introduction to the benefits and features of the Logging Application Block. If implemented consistently throughout a system, it should provide a robust and powerful tool for both debugging and monitoring. The information given in this article should allow you to start incorporating the block into your code.

At the very least, I hope the article has highlighted the benefits of thinking about logging early in a project, and choosing a consistent approach (whether that be with Log4Net, NSpring, the Logging Application Block, System.Diagnostics.Trace, or a home grown framework).

Finally, you may want to wait for the new Enterprise Library. In which case, the concepts introduced in this article should help you to get up to speed with it quickly.

Revision History

05 Jan 2005:

• Hopefully, I have made it clear that the sample provided with this article (LoggingBlockInvestigator.exe) is distinct from the TraceViewer.exe sample provided with the EIF by Microsoft.

10 Feb 2005:

• The Enterprise Library has now been launched. I have re-written this article as Get Logging with the Enterprise Library.