Chapter 4 - As Easy As Falling Off a Log

Introduction

Just in case you didn't quite grasp it from the title, this chapter is about one of the most useful and popular of the Enterprise Library blocks, the Logging application block, which makes it really easy to perform logging in a myriad of different ways depending on the requirements of your application.

Logging generally fulfills two main requirements: monitoring general application performance, and providing information. In terms of performance, logging allows you to monitor what's happening inside your application and, in some cases, what's happening in the world outside as well. For example, logging can indicate what errors or failures have occurred, when something that should have happened did not, and when things are taking a lot longer than they should. It can also simply provide status information on processes that are working correctly—including those that talk to the outside world. Let's face it, there's nothing more rewarding for an administrator than seeing an event log full of those nice blue information icons.

Secondly, and possibly even more importantly, logging can provide vital information about your application. Often referred to as auditing, this type of logging allows you to track the behavior of users and processes in terms of the tasks they carry out, the information they read and change, and the resources they access. It can provide an audit trail that allows you to follow up and get information about malicious activity (whether it succeeds or not), will allow you to trace events that may indicate future attack vectors or reveal security weaknesses, and even help you to recover when disaster strikes (though this doesn't mean you shouldn't be taking the usual precautions such as backing up systems and data). One other area where audit logging is useful is in managing repudiation. For example, your audit logs may be useful in legal or procedural situations where users or external attackers deny their actions.

The Logging block is a highly flexible and configurable solution that allows you to create and store log messages in a wide variety of locations, categorize and filter messages, and collect contextual information useful for debugging and tracing as well as for auditing and general logging requirements. It abstracts the logging functionality from the log destination so that the application code is consistent, irrespective of the location and type of the target logging store. Changes to almost all of the parameters that control logging are possible simply by changing the configuration after deployment and at run time. This means that administrators and operators can vary the logging behavior as they manage the application, including when using Group Policy.

What Does the Logging Block Do?

The Logging application block allows you to decouple your logging functionality from your application code. The block can route log entries to a Windows® Event Log, a database, or a text (or XML) file. It can also generate an e-mail message containing the logging information, a message you can route through Windows Message Queuing (using a distributor service provided with the block), or a Windows Management Instrumentation (WMI) event. And, if none of these built-in capabilities meets your requirements, you can create a provider that sends the log entry to any other custom location or executes some other action.

In your application, you simply generate a log entry using a suitable logging object, such as the LogWriter class, and then call a method to write the information it contains to the logging system. The Logging block routes the log message through any filters you define in your configuration, and on to the listeners that you configure. Each listener defines the target of the log entry, such as Windows Event Log or an e-mail message, and uses a formatter to generate suitably formatted content for that logging target.

You can see from this that there are many objects involved in this multi-step process, and it is important to understand how they interact and how the log message flows through the pipeline of processes. Figure 1 shows the overall process in more detail, and provides an explanation of each stage.

Figure 1

An overview of the logging process and the objects in the Logging block

Stage	Description
Creating the Log Entry	The user creates a LogWriter instance, uses it to create a new LogEntry, and passes it to the Logging block for processing. Alternatively, the user can create a new LogEntry explicitly, populate it with the required information, and use a LogWriter to pass it to the Logging block for processing.
Filtering the Log Entry	The Logging block filters the LogEntry (based on your configuration settings) for message priority, or categories you added to the LogEntry when you created it. It also checks to see if logging is enabled. These filters can prevent any further processing of the log entries. This is useful, for example, when you want to allow administrators to enable and disable additional debug information logging without requiring them to restart the application.
Selecting Trace Sources	Trace sources act as the link between the log entries and the log targets. There is a trace source for each category you define in the logging block configuration; plus, there are three built-in trace sources that capture all log entries, unprocessed entries that do not match any category, and entries that cannot be processed due to an error while logging (such as an error while writing to the target log).
Selecting Trace Listeners	Each trace source has one or more trace listeners defined. These listeners are responsible for taking the log entry, passing it through a separate log formatter that translates the content into a suitable format, and passing it to the target log. Several trace listeners are provided with the block, and you can create your own if required.
Formatting the Log Entry	Each trace listener can use a log formatter to format the information contained in the log entry. The block contains log message formatters, and you can create your own formatter if required. The text formatter uses a template containing placeholders that makes it easy to generate the required format for log entries.

Logging Categories

Categories allow you to specify the target(s) for log entries processed by the block. You can define categories that relate to one or more targets. For example, you might create a category named General containing trace listeners that write to text files and XML files, and a category named Auditing for administrative information that is configured to use trace listeners that write to one or more databases. Then you can assign a log entry to one or more categories, effectively mapping it to multiple targets. The three log sources shown in the schematic in Figure 1 (all events log source, not processed log source, and errors log source) are themselves categories for which you can define trace listeners.

Note

Logging is an added-value service for applications, and so any failures in the logging process must be handled gracefully without raising an exception to the main business processes. The Logging block achieves this by sending all logging failures to a special category (the errors log source) which is named Logging Errors & Warnings. By default, these error messages are written to Windows Event Log, though you can configure this category to write to other targets using different trace listeners if you wish.

Logging Overhead and Additional Context Information

No matter how you implement logging, it will always have some performance impact. The Logging block provides a flexible and highly configurable logging solution that is carefully designed to minimize performance impact. However, you should be aware of this impact, and consider how your own logging strategy will affect it. For example, a complex configuration that writes log entries to multiple logs and uses multiple filters is likely to have more impact than simple configurations. You must balance your requirements for logging against performance and scalability needs.

To maximize performance, the LogWriter class by default exposes properties only for the commonly required information. This includes the event ID, message, priority, and categories you specify in the configuration. The LogWriter also automatically collects some context information such as the time, the application domain, the machine name, and the process ID—where possible—using cached values in order to minimize performance impact.

However, collecting additional context information can be expensive in processing terms and, if you are not going to use the information, wastes precious resources and may affect performance. Therefore, the Logging block only collects other less commonly used information from the environment, which you might require only occasionally, if you specify that you want this information when you create the LogEntry instance. Four classes within the Logging block can collect specific sets of context information that you can add to your log entry. This includes COM+ diagnostic information, the current stack trace, the security-related information from the managed runtime, and security-related information from the operating system. There is also a dictionary property for the log entry where you can add any additional custom information you require, and which must appear in your logs.

How Do I Use the Logging Block?

It's time to see some examples of the Logging block use, including how to create log entries and write them to various targets such as the Windows Event Log, disk files, and a database. Later you'll see how you can use some of the advanced features of the block, such as checking filter status and adding context information to a log entry. However, before you can start using the Logging block, you must configure it.

Configuring the Logging Block

You can configure the Logging block using the configuration tool described in Chapter 1, "Introduction." The logging settings section of the configuration tool contains three columns where you configure filters (trace sources), logging target listeners (trace listeners), and log message formatters. The first column contains three types of filter: categories (category sources), special categories, and logging filters. All of these items were described in the schematic shown in Figure 1 and the accompanying table.

Figure 2 shows the configuration tool loaded with the configuration for the examples used in this chapter. You can see that we have configured several types of filters, listeners, and formatters. As the configuration contains the Database trace listener, the configuration tool has automatically added the Database Settings section as well.

Figure 2

The configuration settings for the sample application

The easiest way to learn about how the Logging block configuration works is to run the configuration tool yourself and open the App.config file from the example application. You can expand each of the sections to see the property settings, and to relate each item to the others.

Initializing the Logging Block

Now you must edit your code to use the Logging block. You'll need to add references to the appropriate Enterprise Library assemblies and namespaces. The assemblies you must add to your project (in addition to the assemblies required for all Enterprise Library projects) are:

• Microsoft.Practices.EnterpriseLibrary.Logging.dll
• Microsoft.Practices.EnterpriseLibrary.Logging.Database.dll
• Microsoft.Practices.EnterpriseLibrary.Data.dll

However, if you do not intend to send log entries to a database, you will not require the last two assemblies on this list.

Now you are ready to write some code.

Diving in with an Example

To demonstrate the features of the Logging block, we provide a sample application that you can download and run on your own computer. You can run the executable directly from the bin\Debug folder, or you can open the solution named Logging in Microsoft® Visual Studio® to see the code and run it under Visual Studio. The application includes a preconfigured database for storing log entries, as well as scripts you can use to create the Logging database within a different database server if you prefer.

Note

You do not need to run the scripts if you have Microsoft SQL Server® Express installed locally. If you want to specify a different database for logging, edit the script named CreateLoggingDb.cmd to specify the location of the database and execute it. After you do that, you must change the connection string named ExampleDatabase to point to your new database.
In addition, depending on the version of the operating system you are using, you may need to execute the application under the context of an account with administrative privileges. If you are running the sample from within Visual Studio, start Visual Studio by right-clicking the entry in your Start menu and selecting Run as administrator.

One other point to note about the sample application is that it creates a folder named Temp in the root of your C: drive if one does not already exist, and writes the text log files there so that you can easily find and view them.

Creating and Writing Log Entries with a LogWriter

The first of the examples, Simple logging with the Write method of a LogWriter, demonstrates how you can use a LogWriter directly to create log entries. The first stage is to obtain a LogWriter, and the example uses the simplest approach—the GetInstance method of the current Enterprise Library container. See the following code.

// Resolve the default LogWriter object from the container.
LogWriter defaultWriter 
          = EnterpriseLibraryContainer.Current.GetInstance<LogWriter>();

Now you can call the Write method and pass in any parameter values you require. There are many overloads of the Write method. They allow you to specify the message text, the category, the priority (a numeric value), the event ID, the severity (a value from the TraceEventType enumeration), and a title for the event. There is also an overload that allows you to add custom values to the log entry by populating a Dictionary with name and value pairs (you will see this used in a later example). Our example code uses several of these overloads. We've removed some of the Console.WriteLine statements from the code listed here to make it easier to see what it actually does.

// Check if logging is enabled before creating log entries.
if (defaultWriter.IsLoggingEnabled())
{
  defaultWriter.Write("Log entry created using the simplest overload.");
  defaultWriter.Write("Log entry with a single category.", "General");
  defaultWriter.Write("Log entry with a category, priority, and event ID.",
                      "General", 6, 9001);
  defaultWriter.Write("Log entry with a category, priority, event ID, "
                      + "and severity.", "General", 5, 9002,
                      TraceEventType.Warning);
  defaultWriter.Write("Log entry with a category, priority, event ID, "
                      + "severity, and title.", "General", 8, 9003,
                      TraceEventType.Warning, "Logging Block Examples");
}
else
{
  Console.WriteLine("Logging is disabled in the configuration.");
}

Notice how the code first checks to see if logging is enabled. There is no point using valuable processor cycles and memory generating log entries if they aren't going anywhere. The Filters section of the Logging block configuration can contain a special filter named the Log Enabled Filter (we have configured one in our example application). This filter has the single property, Enabled, that allows administrators to enable and disable all logging for the block. When it is set to False, the IsLoggingEnabled property of the LogWriter will return false as well.

The example produces the following result. All of the events are sent to the General category, which is configured to write events to the Windows Application Event Log (this is the default configuration for the block).

Created a Log Entry using the simplest overload.
Created a Log Entry with a single category.
Created a Log Entry with a category, priority, and event ID.
Created a Log Entry with a category, priority, event ID, and severity.
Created a Log Entry with a category, priority, event ID, severity, and title.
Open Windows Event Viewer 'Application' Log to see the results.

You can open Windows Event Viewer to see the results. Figure 3 shows the event generated by the last of the Write statements in this example.

Figure 3

The logged event

t

Writing Log Entries to Multiple Categories

In addition to being able to define multiple categories, you can send a log entry to more than one category in a single operation. This approach often means you can define fewer categories, and it simplifies the configuration because each category can focus on a specific task. You don't need to have multiple categories with similar sets of trace listeners.

The second example, Logging to multiple categories with the Write method of a LogWriter, shows how to write to multiple categories. The example has two categories, named DiskFiles and Important, defined in the configuration. The DiskFiles category contains references to a flat file trace listener and an XML trace listener. The Important category contains references to an event log trace listener and a rolling flat file trace listener.

The example uses the following code to create an array of the two category names, DiskFiles and Important, and then it writes three log messages to these two categories using the Write method of the LogWriter in the same way as in the previous example. Again, we've removed some of the Console.WriteLine statements to make it easier to see what the code actually does.

// Check if logging is enabled before creating log entries.
if (defaultWriter.IsLoggingEnabled())
{
  // Create a string array (or List<>) containing the categories.
  string[] logCategories = new string[] {"DiskFiles", "Important"};

  // Write the log entries using these categories.
  defaultWriter.Write("Log entry with multiple categories.", logCategories);
  defaultWriter.Write("Log entry with multiple categories, a priority, "
                      + "and an event ID.", logCategories, 7, 9004);
  defaultWriter.Write("Log entry with multiple categories, a priority, "
                      + "event ID, severity, and title.", logCategories, 10, 
                      9005, TraceEventType.Critical, "Logging Block Examples");
}
else
{
  Console.WriteLine("Logging is disabled in the configuration.");
}

Controlling Output Formatting

If you run the example above and then open Windows Event Log, you will see the three events generated by this example. Also, in the C:\Temp folder, you will see three files. RollingFlatFile.log is generated by the rolling flat file trace listener, and contains the same information as the event log event generated by the event log trace listener. If you explore the configuration, you will see that they both use the same text formatter to format the output.

The FlatFile.log file, which is generated by the flat file trace listener, contains only a simplified set of values for each event. For example, this is the output generated for the last of the three log entries.

----------------------------------------
Timestamp: 24/11/2009 10:49:26
Message: Log entry with multiple categories, a priority, event ID, severity, and title.
Category: DiskFiles, Important
Priority: 10
EventId: 9005
ActivityId: 00000000-0000-0000-0000-000000000000
Severity: Critical
Title:Logging Block Examples
----------------------------------------

The reason is that the flat file trace listener is configured to use a different text formatter—in this case one named Brief Format Text (listed in the Formatters section of the configuration tool). All trace listeners use a formatter to translate the contents of the log entry properties into the appropriate format for the target of that trace listener. Trace listeners that create text output, such as a text file or an e-mail message, use a text formatter defined within the configuration of the block.

If you examine the configured text formatter, you will see that it has a Template property. You can use the Template Editor dialog available for editing this property to change the format of the output by adding tokens (using the drop-down list of available tokens) and text, or by removing tokens and text. Figure 5 shows the default template for a text formatter, and how you can edit this template. A full list of tokens and their meaning is available in the online documentation for Enterprise Library, although most are fairly self-explanatory.

Figure 5

Editing the template for a text formatter

The template we used in the Brief Format text formatter is shown here.

Timestamp: {timestamp(local)}{newline}Message: {message}{newline}Category: {category}{newline}Priority: {priority}{newline}EventId: {eventid}{newline}ActivityId: {property(ActivityId)}{newline}Severity: {severity}{newline}Title:{title}{newline}

Non-Formatted Trace Listeners

While we are discussing output formatting, there is one other factor to consider. Some trace listeners do not use a text formatter to format the output they generate. This is generally because the output is in a binary or specific format. The WMI trace listener is a typical example that does not use a text formatter.

For such trace listeners, you can set the TraceOutputOptions property to one of a range of values to specify the values you want to include in the output. The TraceOutputOptions property accepts a value from the System.Diagnostics.TraceOptions enumeration. Valid values include CallStack, DateTime, ProcessId, LogicalOperationStack, Timestamp, and ThreadId. The documentation installed with Enterprise Library, and the documentation for the System.Diagnostics namespace on MSDN®, provide more information.

Filtering by Severity in a Trace Listener

The previous example generates a third disk file that we haven't looked at yet. We didn't forget this, but saved if for this section because it demonstrates another feature of the trace listeners that you will often find extremely useful. To see this, you need to view the file XmlLogFile.xml that was generated in the C:\Temp folder by the XML trace listener we used in the previous example. You should open it in Microsoft Internet Explorer® (or another Web browser or text editor) to see the structure.

You will see that the file contains only one event from the previous example, not the three that the code in the example generated. This is because the XML trace listener has the Filter property in its configuration set to Error. Therefore, it will log only events with a severity of Error or higher. If you look back at the example code, you will see that only the last of the three calls to the Write method specified a value for the severity (TraceEventType.Critical in this case), and so the default value Information was used for the other two events.

Note

If you get an error indicating that the XML document created by the XML trace listener is invalid, it's probably because you have more than one log entry in the file. This means that it is not a valid XML document—it contains separate event log entries added to the file each time you ran this example. To view it as XML, you must open the file in a text editor and add an opening and closing element (such as <root> and </root>) around the content. Or, just delete it and run the example once more.

All of the trace listeners provided with Enterprise Library expose the Filter property, and you can use this to limit the log entries written to the logging target to only those that are important to you. If your code generates many information events that you use for monitoring and debugging only under specific circumstances, you can filter these to reduce the growth and size of the log when they are not required.

Alternatively, (as in the example) you can use the Filter property to differentiate the granularity of logging for different listeners in the same category. It may be that a flat file trace listener will log all entries to an audit log file for some particular event, but an Email trace listener in the same category will send e-mail messages to administrators only when an Error or Critical event occurs.

Filtering All Log Entries by Priority

As well as being able to filter log entries in individual trace listeners based on their severity, you can set the Logging block to filter all log entries sent to it based on their priority. Alongside the log-enabled filter and category filter in the Filters section of the configuration (which we discussed earlier in this chapter), you can add a filter named Priority Filter.

This filter has two properties that you can set: Minimum Priority and Maximum Priority. The default setting for the priority of a log entry is -1, which is the same as the default setting of the Minimum Priority property of the filter, and there is no maximum priority set. Therefore, this filter will not block any log entries. However, if you change the defaults for these properties, only log entries with a priority between the configured values (including the specified maximum and minimum values) will be logged. The exception is log entries that have the default priority of -1. These are never filtered.

Creating and Using LogEntry Objects

So far we have used the Write method of the LogWriter class to generate log entries. An alternative approach that may be useful if you want to create log entries individually, perhaps to return them from methods or to pass them between processes, is to generate instances of the LogEntry class and then write them to the configured targets afterwards.

The example, Creating and writing log entries with a LogEntry object, demonstrates this approach. It creates two LogEntry instances. The code first calls the most complex constructor of the LogEntry class that accepts all of the possible values. This includes a Dictionary of objects with a string key (in this example, the single item Extra Information) that will be included in the output of the trace listener and formatter. Then it writes this log entry using an overload of the Write method of the LogWriter that accepts a LogEntry instance.

Next, the code creates a new empty LogEntry using the default constructor and populates this by setting individual properties, before writing it using the same Write method of the LogWriter.

// Check if logging is enabled before creating log entries.
if (defaultWriter.IsLoggingEnabled())
{
  // Create a Dictionary of extended properties
  Dictionary<string, object> exProperties = new Dictionary<string, object>();
  exProperties.Add("Extra Information", "Some Special Value");  

  // Create a LogEntry using the constructor parameters. 
  LogEntry entry1 = new LogEntry("LogEntry with category, priority, event ID, " 
                                 + "severity, and title.", "General", 8, 9006,
                                 TraceEventType.Error, "Logging Block Examples",
                                 exProperties);
  defaultWriter.Write(entry1);

  // Create a LogEntry and populate the individual properties.
  LogEntry entry2 = new LogEntry();
  entry2.Categories = new string[] {"General"};
  entry2.EventId = 9007;
  entry2.Message = "LogEntry with individual properties specified.";
  entry2.Priority = 9;
  entry2.Severity = TraceEventType.Warning;
  entry2.Title = "Logging Block Examples";
  entry2.ExtendedProperties = exProperties;  
  defaultWriter.Write(entry2);
}
else
{
  Console.WriteLine("Logging is disabled in the configuration.");
}

This example writes the log entries to the Windows Application Event Log by using the General category. If you view the events this example generates, you will see the values set in the code above including (at the end of the list) the extended property we specified using a Dictionary. You can see this in Figure 6.

Figure 6

A log entry written to the General category

An Example of Using Special Sources

The example, Using Special Sources to capture unprocessed events or errors, demonstrates how the Logging block reacts under these two circumstances. The code first writes a log entry to a category named InvalidCategory, which does not exist in the configuration. Next, it writes another log entry to a category named CauseLoggingError that is configured to use a Database trace listener. However, this trace listener specifies a connection string that is invalid; it points to a database that does not exist.

// Check if logging is enabled before creating log entries.
if (defaultWriter.IsLoggingEnabled())
{
  // Create log entry to be processed by the "Unprocessed" special source.
  defaultWriter.Write("Entry with category not defined in configuration.",
                      "InvalidCategory");

  // Create log entry to be processed by the "Errors & Warnings" special source.
  defaultWriter.Write("Entry that causes a logging error.", "CauseLoggingError");
}
else
{
  Console.WriteLine("Logging is disabled in the configuration.");
}

You might expect that neither of these log entries would actually make it to their target. However, the example generates the following messages that indicate where to look for the log entries that are generated.

Created a Log Entry with a category name not defined in the configuration.
The Log Entry will appear in the Unprocessed.log file in the C:\Temp folder.

Created a Log Entry that causes a logging error.
The Log Entry will appear in the Windows Application Event Log.

This occurs because we configured the Unprocessed Category in the Special Sources section with a reference to a flat file trace listener that writes log entries to a file named Unprocessed.log. If you open this file, you will see the log entry that was sent to the InvalidCategory category.

The example uses the default configuration for the Logging Errors & Warnings special source. This means that the log entry that caused a logging error will be sent to the formatted event log trace listener referenced in this category. If you open the application event log, you will see this log entry. The listing below shows some of the content.

Timestamp: 24/11/2009 15:14:30
Message: Tracing to LogSource 'CauseLoggingError' failed. Processing for other sources will continue. See summary information below for more information. Should this problem persist, stop the service and check the configuration file(s) for possible error(s) in the configuration of the categories and sinks.

Summary for Enterprise Library Distributor Service:
======================================
--> 
Message: 
Timestamp: 24/11/2009 15:14:30
Message: Entry that causes a logging error.
Category: CauseLoggingError
...
...
Exception Information Details:
======================================
Exception Type: System.Data.SqlClient.SqlException
Errors: System.Data.SqlClient.SqlErrorCollection
Class: 11
LineNumber: 65536
Number: 4060
Procedure: 
Server: (local)\SQLEXPRESS
State: 1
Source: .Net SqlClient Data Provider
ErrorCode: -2146232060
Message: Cannot open database "DoesNotExist" requested by the login. The login failed.
Login failed for user 'xxxxxxx\xxx'.
...
...
StackTrace Information Details: 
======================================
...
...

In addition to the log entry itself, you can see that the event contains a wealth of information to help you to debug the error. It contains a message indicating that a logging error occurred, followed by the log entry itself. However, after that is a section containing details of the exception raised by the logging mechanism (you can see the error message generated by the SqlClient data access code), and after this is the full stack trace.

Note

One point to be aware of is that logging database and security exceptions should always be done in such a way as to protect sensitive information that may be contained in the logs. You must ensure that you appropriately restrict access to the logs, and only expose non-sensitive information to other users. You may want to consider applying exception shielding, as described in Chapter 3, "Error Management Made Exceptionally Easy."

Logging to a Database

One of the most common requirements for logging, after Windows Event Log and text files, is to store log entries in a database. The Logging block contains the database trace listener that makes this easy. You configure the database using a script provided with Enterprise Library, located in the \Blocks\Logging\Src\DatabaseTraceListener\Scripts folder of the source code. We also include these scripts with the example for this chapter.

The scripts assume that you will use the locally installed SQL Server Express database, but you can edit the CreateLoggingDb.cmd file to change the target to a different database server. The SQL script that the command file executes creates a database named Logging, and adds the required tables and stored procedures to it.

However, if you only want to run the example application we provide for this chapter, you do not need to create a database. The project contains a preconfigured database file named Logging.mdf (located in the bin\Debug folder) that is auto-attached to your local SQL Server Express instance. You can connect to this database using Visual Studio Server Explorer to see the contents. The configuration of the database trace listener contains the Database Instance property, which is a reference to this database as configured in the settings section for the Data Access application block (see Figure 7).

Figure 7

Configuration of the Database trace listener

Using the Database Trace Listener

The example, Sending log entries to a database, demonstrates the use of the database trace listener. The code is relatively simple, following the same style as the earlier example of creating a Dictionary of extended properties, and then using the Write method of the LogWriter to write two log entries. The first log entry is created by the LogWriter from the parameter values provided to the Write method. The second is generated in code as a new LogEntry instance by specifying the values for the constructor parameters. Also notice how easy it is to add additional information to a log entry using a simple Dictionary as the ExtendedProperties of the log entry.

// Check if logging is enabled before creating log entries.
if (defaultWriter.IsLoggingEnabled())
{
  // Create a Dictionary of extended properties
  Dictionary<string, object> exProperties = new Dictionary<string, object>();
  exProperties.Add("Extra Information", "Some Special Value");

  // Create a LogEntry using the constructor parameters.
  defaultWriter.Write("Log entry with category, priority, event ID, severity, "
                      + "title, and extended properties.", "Database",
                      5, 9008, TraceEventType.Warning, 
                      "Logging Block Examples", exProperties);

  // Create a LogEntry using the constructor parameters. 
  LogEntry entry = new LogEntry("LogEntry with category, priority, event ID, "
                                + "severity, title, and extended properties.",
                                "Database", 8, 9009, TraceEventType.Error, 
                                "Logging Block Examples", exProperties);
  defaultWriter.Write(entry);
}
else
{
  Console.WriteLine("Logging is disabled in the configuration.");
}

To see the two log messages created by this example, you can open the Logging.mdf database from the bin\Debug folder using Visual Studio Server Explorer. You will find that the FormattedMessage column of the second message contains the following. You can see the extended property information we added using a Dictionary at the end of the message.

Timestamp: 03/12/2009 17:14:02
Message: LogEntry with category, priority, event ID, severity, title, and extended properties.
Category: Database
Priority: 8
EventId: 9009
Severity: Error
Title: Logging Block Examples
Activity ID: 00000000-0000-0000-0000-000000000000
Machine: BIGFOOT
App Domain: LoggingExample.vshost.exe
ProcessId: 5860
Process Name: E:\Logging\Logging\bin\Debug\LoggingExample.vshost.exe
Thread Name: 
Win32 ThreadId:3208
Extended Properties: Extra Information - Some Special Value

Note that you cannot simply delete logged information due to the references between the Log and CategoryLog tables. However, the database contains a stored procedure named ClearLogs that you can execute to remove all log entries.

Note

The connection string for the database we provide with this example is:
Data Source=.\SQLEXPRESS;AttachDbFilename=|DataDirectory|\Logging.mdf;Integrated Security=True;User Instance=True
If you have configured a different database using the scripts provided with Enterprise Library, you may find that you get an error when you run this example. It is likely to be that you have an invalid connection string in your App.config file for your database. In addition, use the Services applet in your Administrative Tools folder to check that the SQL Server (SQLEXPRESS) database service (the service is named MSSQL$SQLEXPRESS) is running.

Testing Logging Filter Status

As you've seen in earlier examples, the Logging block allows you to check if logging is enabled before you create and write a log entry. You can avoid the additional load that this places on your application if logging is not enabled. However, even when logging is enabled, there is no guarantee that a specific log entry will be written to the target log store. For example, it may be blocked by a priority filter if the message priority is below a specified level, or it may belong only to one or more categories where the relevant category filter(s) have logging disabled (a common scenario in the case of logging code specifically designed only for debugging use).

The example, Checking filter status and adding context information to the log entry, demonstrates how you can check if a specific log entry will be written to its target before you actually call the Write method. After checking that logging is not globally disabled, the example creates two LogEntry instances with different categories and priorities. It passes each in turn to another method named ShowDetailsAndAddExtraInfo. The following is the code that creates the LogEntry instances.

// Check if logging is enabled before creating log entries.
if (defaultWriter.IsLoggingEnabled())
{
  // Create a new LogEntry with two categories and priority 3.
  string[] logCategories = new string[] {"General", "DiskFiles"};
  LogEntry entry1 = new LogEntry("LogEntry with categories 'General' and "
                                 + "'DiskFiles' and Priority 3.", logCategories,
                                 3, 9009, TraceEventType.Error, 
                                 "Logging Block Examples", null);
  ShowDetailsAndAddExtraInfo(entry1);

  // Create a new LogEntry with one category and priority 1.
  logCategories = new string[] { "BlockedByFilter" };
  LogEntry entry2 = new LogEntry("LogEntry with category 'BlockedByFilter' and "
                                 + "Priority 1.", logCategories, 1, 9010, 
                                 TraceEventType.Information, 
                                 "Logging Block Examples", null);
  ShowDetailsAndAddExtraInfo(entry2);
}
else
{
  Console.WriteLine("Logging is disabled in the configuration.");
}

The ShowDetailsAndAddExtraInfo method takes a LogEntry instance and does two different things. Firstly, it shows how you can obtain information about the way that the Logging block will handle the log entry. This may be useful in advanced scenarios where you need to be able to programmatically determine if a specific log entry was detected by a specific trace source, or will be written to a specific target. Secondly, it demonstrates how you can check if specific filters, or all filters, will block a log entry from being written to its target.

Obtaining Information about Trace Sources and Trace Listeners

The first section of the ShowDetailsAndAddExtraInfo method iterates through the collection of trace sources (LogSource instances) exposed by the GetMatchingTraceSources method of the LogWriter class. Each LogSource instance exposes a Listeners collection that contains information about the listeners (which specify the targets to which the log entry will be sent).

void ShowDetailsAndAddExtraInfo(LogEntry entry)
{
  // Display information about the Trace Sources and Listeners for this LogEntry. 
  IEnumerable<LogSource> sources = defaultWriter.GetMatchingTraceSources(entry);
  foreach (LogSource source in sources)
  {
    Console.WriteLine("Log Source name: '{0}'", source.Name);
    foreach (TraceListener listener in source.Listeners)
    {
      Console.WriteLine(" - Listener name: '{0}'", listener.Name);
    }
  }
  ...

Checking if Filters Will Block a Log Entry

Next, the ShowDetailsAndAddExtraInfo method checks if any filters will block the current log entry. There are two ways you can do this. You can query each filter type in turn, or just a specific filter type, by using the GetFilter method of the LogWriter class to get a reference to that type of filter. Then you can check if this filter is enabled, and also use the ShouldLog method (to which you pass the list of categories for the log entry) to see if logging will succeed.

The following code shows this approach. It also shows the simpler approach that you can use if you are not interested in the result for a specific filter type. The LogWriter class also exposes the ShouldLog method, which indicates if any filters will block this entry.

  ...
  // Check if any filters will block this LogEntry.
  // This approach allows you to check for specific types of filter.
  // If there are no filters of the specified type configured, the GetFilter 
  // method returns null, so check this before calling the ShouldLog method.
  CategoryFilter catFilter = defaultWriter.GetFilter<CategoryFilter>();
  if (null == catFilter || catFilter.ShouldLog(entry.Categories))
  {
    Console.WriteLine("Category Filter(s) will not block this LogEntry.");
  }
  else
  {
    Console.WriteLine("A Category Filter will block this LogEntry.");
  }

  PriorityFilter priFilter = defaultWriter.GetFilter<PriorityFilter>();
  if (null == priFilter || priFilter.ShouldLog(entry.Priority))
  {
    Console.WriteLine("Priority Filter(s) will not block this LogEntry.");
  }
  else
  {
    Console.WriteLine("A Priority Filter will block this LogEntry.");
  }

  // Alternatively, a simple approach can be used to check for any type of filter
  if (defaultWriter.ShouldLog(entry))
  {
    Console.WriteLine("This LogEntry will not be blocked by config settings.");
    ....
    // Add context information to log entries after checking that the log entry
    // will not be blocked due to configuration settings. See the following
    // section 'Adding Additional Context Information' for details.
    ....
  }
  else
  {
    Console.WriteLine("This LogEntry will be blocked by configuration settings.");
  }
}

After you determine that logging will succeed, you can add extra context information and write the log entry. You'll see the code to achieve this shortly. In the meantime, this is the output generated by the example. You can see that it contains details of the log (trace) sources and listeners for each of the two log entries created by the earlier code, and the result of checking if any category filters will block each log entry.

Created a LogEntry with categories 'General' and 'DiskFiles'.
Log Source name: 'General'
 - Listener name: 'Formatted EventLog TraceListener'
Log Source name: 'DiskFiles'
 - Listener name: 'FlatFile TraceListener'
 - Listener name: 'XML Trace Listener'
Category Filter(s) will not block this LogEntry.
Priority Filter(s) will not block this LogEntry.
This LogEntry will not be blocked due to configuration settings.
...
Created a LogEntry with category 'BlockedByFilter', and Priority 1.
Log Source name: 'BlockedByFilter'
 - Listener name: 'Formatted EventLog TraceListener'
A Category Filter will block this LogEntry.
A Priority Filter will block this LogEntry.
This LogEntry will be blocked due to configuration settings.

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!

Tracing and Correlating Activities

The final topic for this chapter demonstrates another feature of the Logging block that makes it easier to correlate multiple log entries when you are trying to trace or debug some recalcitrant code in your application. 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.

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

Creating Custom Trace Listeners, Filters, and Formatters

You can extend the capabilities of the Logging block if you need to add specific functionality to it. In general, you will only need to implement custom log filters, trace listeners, or log formatters. The design of the block makes it easy to add these and make them available through configuration.

To create a new log filter, you can either implement the ILogFilter interface, which specifies the single method Filter that must accept an instance of a LogEntry and return true or false, or you can inherit the base class LogFilter and implement the Filter method.

To create a custom trace listener, you can inherit from the abstract base class CustomTraceListener and implement the methods required to send your log entry to the appropriate location or execute the relevant actions to log the message. You can expose a property for the relevant log formatter if you want to allow users to select a specific formatter for the message.

To create a custom log formatter, you can either implement the ILogFormatter interface, which specifies the single method, Format, that must accept an instance of a LogEntry and return the formatted message, or you can inherit the base class, LogFormatter, and implement the Format method.

For more information about extending the Logging block, see the online documentation at https://go.microsoft.com/fwlink/?LinkId=188874 or consult the installed help files.

Summary

This chapter described the Enterprise Library Logging Application Block. This block is extremely useful for logging activities, events, messages, and other information that your application must persist or expose—both to monitor performance and to generate auditing information. The Logging block is, like all of the other Enterprise Library blocks, highly customizable and driven through configuration so that you (or administrators and operations staff) can modify the behavior to suit your requirements exactly.

You can use the Logging block to categorize, filter, and write logging information to a wide variety of targets, including Windows event logs, e-mail messages, disk files, Windows Message Queuing, and a database. You can even collect additional context information and add it to the log entries automatically, and add activity IDs to help you correlate related messages and activities. And, if none of the built-in features meets your requirements, you can create and integrate custom listeners, filters, and formatters.

This chapter explained why you should consider decoupling your logging features from your application code, what the Logging block can do to help you implement flexible and configurable logging, and how you actually perform the common tasks related to logging. For more information about using the Logging block, see the online documentation at https://go.microsoft.com/fwlink/?LinkId=188874 or consult the installed help files.

Next | Previous | Home | Community