Design of the Logging and Instrumentation Application Block
| The design goals for the Logging and Instrumentation Application Block were to make it easy for developers to accomplish the most common application logging and instrumentation tasks and to do so in a consistent manner. To meet this design goal, the block provides a high degree of configurability and leverages two service façades that determine which actions to take based upon the configuration information and not the code. This allows all logging and tracing decisions to be externalized through configuration and lets changes to the logging behavior occur without changes to an application's code. While this makes it simple to accomplish the most common logging and instrumentation tasks, it does not preclude the ability to leverage many of the other classes that exist in the block. Furthermore, if you have logging needs that are not directly covered by the Logging and Instrumentation Application Block, its many extension points let you customize the block to fit your needs. This section discusses the classes that exist in the block and the role they play in logging, not only to explain these extension points, but to also explain how logging in the Logging and Instrumentation Application Block works underneath the covers. To do so, this section reviews each class in the order that it comes into play as a message gets logged. I've broken this flow into several categories: log creation, filtering, log distribution, and routing (including Formatters and Sinks). This section concludes with a discussion of the design for tracing and how it relates to logging in this block. Log CreationThe first step in logging information is to create the entry that will eventually be logged. One of the challenges in providing a generic solution that represents a log entry for any application is determining what information is needed for every log entry, what information is not mandatory but important enough to include in every log entry, and how to provide a solution that allows any application with the ability to include other extra information that may only be pertinent to that application. Another challenge that must be overcome involves designing a solution that is flexible enough to accommodate virtually any type of log information without being so complex that it is difficult to use or causes major performance issues in an application. The primary classes that are involved in the log creation process are the Logger, LogWriter, LogEntry, ContextItems, and ExtraInformationProviders. Figure 6.1 shows the relationship between these classes except for ExtraInformationProviders, which will be discussed a bit later in this chapter. Figure 6.1. Primary Classes for Creating Logs Basic LoggingLike the other application blocks, the Logging and Instrumentation Application Block achieves its design goal of a simplified programming interface by exposing a service façade; in this case, it is the Logger class. The Logger interface only exposes one method for logging informationa static Write method. This method is overloaded ten times, so technically it is really more than one method. The point, however, is that to log information in an application, the only method that needs to be called is Write. The implementation for how and where to log information happens behind the Logger service façade. The Logging and Instrumentation Application Block is a message-based architecture. The Logger creates the message. This message is called the LogEntry. The Logger encapsulates a LogWriter object for publishing the message. The LogWriter filters the messages based on the Category and Priority of the LogEntry and, if it passes the filter, sends the LogEntry to the appropriate distribution strategy. This all happens in the process space of the running application. The distribution strategy then sends the message to a distributor, and the distributor determines how the message should be routed to a specific destination (also known as a Sink). Figure 6.2 illustrates how the Logging and Instrumentation Application Block works to synchronously distribute the logs that are created in different applications. Figure 6.2. Synchronous Distribution of Logs The overloads for the Logger's Write method simply represent different ways to create an instance of a LogEntry. One overload accepts an instance of a LogEntry object; the other overloads accept various fields from which a LogEntry can be created. The simplest way to automatically create a LogEntry is to call the Write method that takes a single string representing the LogEntry's Message property. Listing 6.1 shows an example of this. The Logger class will use this string to create a LogEntry with default values for all of the other LogEntry properties. Listing 6.1. Creating a LogEntry with a Message
Other overloads allow different combinations of certain LogEntry properties to be populated. For example, Listing 6.2 creates the same LogEntry as Listing 6.1 but with the Category myCategory instead of the one that is configured to be the default Category. Listing 6.2. Creating a LogEntry with a Message and Category
The constructor for the LogEntry expects the fields detailed in Table 6.1. Thus, in Listing 6.1, default values were used for the Category, Priority, EventID, Title, Severity, and ExtendedProperties. In Listing 6.2, myCategory was used in place of the default Category. The ExtendedProperties field is especially interesting; it represents an instance of a class that implements the IDictionary interface and embodies additional name/value pairs to log that are not part of the LogEntry class. For example, Listing 6.3 could be used to log some characteristics about a user.
Listing 6.3. Creating a LogEntry with ExtendedProperties
Extra InformationThe ExtendedProperties field represents "extra information" to add to the log. As you can see in Listing 6.3, this dictionary can be populated with any (serializable) information that an application may need to add to the log. There are common sets of this extra information that many applications will need to add. It is not information that belongs in every log, but it is common enough to deserve an easy way to create it. For example, it is very common to include user information like the kind added in Listing 6.3. To meet this need, the Logging and Instrumentation Application Block ships with additional classes that will obtain this information and populate an IDictionary with it. Of course, automatically obtaining and populating this information does not come without a performance cost; therefore, these classes should only be used as needed. The classes that ship with the Logging and Instrumentation Application Block are ComPlusExtraInformationProvider, DebugInformationProvider, ManagedSecurityContextInformationProvider, and UnmanagedSecurityContextInformationProvider. They are depicted in Figure 6.3. Figure 6.3. ExtraInformationProvider Classes IExtraInformationProviderThe IExtraInformationProvider interface defines a method to populate an IDictionary with extra information. It is not necessary to implement this interface to pass an IDictionary to the LogEntry class; however, this interface provides a neat method for hiding any complexities that might occur to populate a specific IDictionary. (A better name for the interface might have been IDictionaryPopulater.) The interface provides a method which returns an IDictionary that is aptly named PopulateDictionary(IDictionary dict). ComPlusInformationProviderThe PopulateDictionary method for the ComPlusInformationProvider fills the supplied IDictionary with common COM+ diagnostic information. To retrieve this information from COM+, the ComPlusInformationProvider encapsulates a Context-Utils object which in turn wraps around the System.EnterpriseServices.ContextUtil class. The IDictionary is filled with the key/values specified in Table 6.2.
DebugInformationProvider.It is very common to want to log information from the debugging subsystem when developing and testing an application. The DebugInformationProvider is intended to facilitate this task. The PopulateDictionary method for the DebugInformationProvider fills the supplied IDictionary with diagnostic information from the debug subsystem. To retrieve this information, the DebugInformationProvider encapsulates a DebugUtils object that retrieves the stack trace. The IDictionary contains a name/value pair named StackTrace that contains a value equal to the corresponding stack trace. Listing 6.4 shows code from the DebugInformationProviderFixture class, which is part of the application block's test project, to show how this works. Listing 6.4. Using DebugInformationProvider to Populate a Dictionary
This produces a dictionary with one key named StackTrace and the value shown (and formatted for legibility purposes) in Listing 6.5. Listing 6.5. Results from Using the DebugInformationProvider
ManagedSecurityContextInformationProvider.Listing 6.3 created a hash table and populated it with user information from Thread.CurrentPrincipal.Identity. Obtaining and logging user information is a very common need for many applications. As such, the Logging and Instrumentation Application Block ships with the ManagedSecurityContextInformationProvider to facilitate this process. Listing 6.6 shows how to rewrite Listing 6.3 to use this class. Listing 6.6. Using ManagedSecurityContextInformationProvider to Fill ExtendedProperties
Notice that there is no code that gets any information from the CurrentPrincipal's Identity. Well, actually there is, but it is all in the ManagedSecurityContextInformationProvider class. This class retrieves the values listed in Table 6.3 from THRead.CurrentPrincipal.Identity and fills the supplied IDictionary with them.
UnmanagedSecurityContextInformationProvider.Unfortunately, not all applications today operate in the .NET managed environment. Yet, the need still exists to obtain and log valuable information about the current user. The UnmanagedSecurityContextInformationProvider gets the security context information from the unmanaged world and leverages a NativeMethods class that calls the native GetUserNameEx and GetSecurityInfo methods to populate its dictionary. The IDictionary is filled with the keys and values listed in Table 6.4.
Custom ExtraInformationProviderAs already mentioned, it isn't required to use an ExtraInformationProvider to supply an IDictionary to the LogEntry class. However, if there is common information that you continually want to log and this information is not represented by any of the ExtraInformationProviders that are supplied with the Logging and Instrumentation Application Block, it makes sense to encapsulate it with a custom ExtraInformationProvider. Creating such a provider is not complicated; the only task you need to implement for the IExtraInformationProvider interface is the PopulateDictionary method. For example, let's say you need to log the configuration information used by an application. As applications rely on configuration information to drive the runtime behavior, logging the configuration information can become as valuable as logging debugging information. To provide this functionality, I have created the ELConfigurationContextInformationProvider. Listing 6.7 shows how its PopulateDictionary method populates the dictionary with an application's Enterprise Library configuration data (the complete source code is on the book's Web site). Listing 6.7. ELConfigurationContextInformationProvider's Populate-Dictionary Method
The log produced includes the configuration data for all of the application blocks that have been configured for that application. Listing 6.8 shows this output (truncated for brevity). Listing 6.8. Log Produced from Using ELConfigurationContextInformationProvider (TRuncated)
More on LogWriter and LogEntryIt might seem that an obvious ExtraInformationProvider would be one that populates the IDictionary with certain machine and application-specific information like MachineName or ProcessId. Such an ExtraInformationProvider isn't needed, however, because the LogEntry class contains several intrinsic properties that contain this system information. Table 6.5 lists these additional intrinsic properties.
These intrinsic properties are automatically collected and populated when a LogEntry is created. Therefore, you don't need to write any other code for this additional information to be logged. Many of these properties can have their values overwritten if necessary. For example, if it were necessary to change the TimeStamp of a LogEntry to a time other than when it was created (perhaps to simulate a delay for testing), it is possible to do so. To do this, the LogEntry must first be created, the TimeStamp property must be set, and then the LogEntry must be passed to the Logger's Write method, which accepts an already created LogEntry. Listing 6.9 shows such an example. Listing 6.9. Setting Intrinsic Oroperties for a LogEntry
Custom LogEntryYou can capture additional information in a LogEntry by creating a class that derives from the LogEntry class. The Logger's Write(LogEntry) method will accept an instance of the LogEntry class or any subclass thereof. This is a powerful feature because it allows a strongly typed object to be defined that can contain additional important information as an enterprise's standard log message. For example, the Microsoft WS-I Basic Security Profile Sample Application[2] leverages Enterprise Library's configuration, data, exception handling, and logging blocks. The data that gets logged to the database for this application contains extra fields to capture information like the ServiceId. It's possible that a custom LogEntry like that shown in Listing 6.10 could have been used to automatically capture this information.
Listing 6.10. Custom LogEntry for the WS-I Basic Security Profile Application Example
The WSILogEntry could then be used to log all the information that the base LogEntry already logsplus the ServiceIdby using code like that shown in Listing 6.11. Listing 6.11. Sample WS-I Basic Security Profile Application Log
However, as powerful as this is, there is a catch to using it. LogEntries are eventually written to their ultimate data store using the Sink and Formatter classes (described later in this chapter). Typically, a Sink uses a Formatter to format the LogEntry before persisting it; usually, this Formatter will be the TextFormatter. The TextFormatter doesn't know anything about any custom properties or fields that may exist in a subclassed LogEntry. Therefore, to persist a custom LogEntry, either a Sink or Formatter must be used that can account for these additional properties. The WMISink, which ships with Enterprise Library, works this way because the custom schema must be registered with WMI prior to its use and no formatting occurs on it. ContextItemsYet one last way to add information to a LogEntry is through the indirect use of an internal class named ContextItems, which wraps around the System.Runtime.Remoting.Messaging.CallContext class. This class is a specialized collection for method calls and provides data slots that are unique to each logical thread of execution. The Logger class exposes two additional static methods for modifying data on the CallContext. SetContextItem and FlushContextItems. SetContextItem adds a key/value pair to the CallContext dictionary. Context items will be recorded with every log entry. FlushContextItems empties the context items dictionary. Because the SetContextItem method actually adds data to the thread's CallContext, every LogEntry that is written on the same thread after a SetContextItem method call will contain the additional data. This data is added to the ExtendedProperties dictionary. To flush the data from any future LogEntries for that thread, the FlushContextItems method must be called. Listing 6.12 adds the AppVersion identifier for all LogEntries written on a specific thread. Listing 6.12. Using SetContextItem and FlushContextItems
So, even though the SetContextItem was only set before the first LogEntry, it applied to both. Listing 6.13 shows the results. Listing 6.13. Results from Using SetContextItem
The Logger's static Write, SetContextItem, and FlushContextItems methods all pass control to an instance of the LogWriter class. The LogWriter's SetContextItem and FlushContextItems methods just use the ContextItems class. The Write method, however, leverages the configuration data that is passed to it from the Configuration Application Block to determine whether the LogEntry should be filtered before it is sent. If the LogEntry passes the filter criteria, the LogWriter then leverages the configuration information passed to it so that it can determine which distribution strategy should be used for this LogEntry. It then sends the LogEntry via that distribution strategy. FilteringFiltering a LogEntry means that the LogEntry is not passed to a distribution strategy and therefore it is not forwarded onto its final endpoint. The LogWriter delegates responsibility for filtering a LogEntry to the LogFilter class, which is an internal class dedicated solely to reading the filter information from the configuration data passed to it and determining whether the log should be filtered based on Category and Priority. It does this by examining all the filters that have been configured and comparing the log's Category and Priority. If any of the filter tests return false, then the LogFilter returns false to the LogWriter and the log is filtered. Otherwise, the LogWriter sends the LogEntry on its way. Figure 6.4 shows the classes involved in filtering a LogEntry. The following overview of Category and Priority filters will help you better understand how the log filtering process works. Figure 6.4. Classes Involved in Filtering CategoriesA Category is a string that represents a collection of Destinations. A Destination holds information about how to format a LogEntry and where a LogEntry will be sent (see the sections on Formatters and Sinks later in this chapter). Many Categories can be defined in the configuration for the Logging and Instrumentation Application Block. The Category to which a LogEntry ultimately belongs is set at runtime when the LogEntry is created; if no Category is set, then the Category that is configured as the default Category will be assigned to the LogEntry. Examples of both of these scenarios were demonstrated in Listings 6.2 and 6.1 respectively. Categories can be leveraged to filter LogEntries. For example, if three CategoriesCategory A, Category B, and Category Cwere configured for an application, the application could be configured to deny all messages except those that belong to Category C and Category B. In this case, LogEntries that have their Category property set to Category A will not be logged. Conversely, the application could be configured to allow all messages except those that only belong to Category A. Figure 6.5 shows a configuration that allows all messages except for those that belong to Category A. Figure 6.5. Filtering Out Category A Whether an application is configured to exclude all Categories listed or to include all Categories listed, the final configuration for Category filters is represented by two constructs: a list of Categories and a flag that indicates whether the list is exclusive (AllowAllExceptDenied) or inclusive (DenyAllExceptAllowed). Either representation can equally define which Categories to allow and which Categories to deny. For example, in the scenario represented by Figure 6.5, {Category A and AllowAllExceptDenied} could also be represented as {(Category B, Category C) and DenyAllExcept-Allowed}. Since only these three Categories exist, they both mean the same thing; however, the first representation only requires one item to be listed, while the second requires two. That's not terribly significant for this scenario; however, it could get unwieldy if there were many Categories. So, the best representation for an application is the one that requires the least number of Categories to be listed. The LogFilter class contains a hash table of filters that have been configured for the application. Filters must implement the IFilter interface; the Logging and Instrumentation Application Block only ships with two such filters: CategoryFilter and PriorityFilter. Although there is a well-defined interface for filters, they are not exposed as an extension point in the Logging and Instrumentation Application Block. The CategoryFilter and PriorityFilter classes implement the IFilter's Filter method. This method accepts a LogEntry and returns a Boolean. The LogFilter class calls all of its configured filters' Filter methods to determine if any of them return false, which would indicate that the LogEntry should be filtered. The logic for the CategoryFilter is pretty straightforward. False is returned if either of the following two conditions is met.
To extend the previous scenario, if a LogEntry was written and its Category property was set as Category A, it would be filtered because the second condition would be met; Category A is in the list and the mode is set to AllowAllExceptDenied. PrioritiesLogEntries can also be filtered based upon Priority. Priority is an integer that represents the significance of the LogEntry. A higher number represents greater importance. Whereas Categories are not only used for filtering but also for setting the formatting and Destination for a LogEntry, Priorities are only used for filtering. If the Priority that is set for a LogEntry is below the configured MinimumPriority for the application, then the LogEntry will be filtered. Log DistributionIf a LogEntry passes the filter criteria, the LogWriter checks the configuration information to determine which distribution strategy has been configured for the application to use. It then passes the LogEntry and all control of writing it to this distribution strategy. The LogWriter's job is now complete; at this point it is the responsibility of the distribution strategy to get the LogEntry to a distributor that can take a single LogEntry and distribute it to all the necessary Destinations. Figure 6.6 highlights the primary classes that are related to log distribution. Figure 6.6. Log Distribution Classes The ILogDistributionStrategy InterfaceTo qualify as a distribution strategy, the ILogDistributionStrategy interface needs to be implemented. This interface only contains a single method definition: SendLog(LogEntrylog). Enterprise Library ships with two implementations of an ILogDistributionStrategy: a synchronous one named InProcLogDistributionStrategy and an asynchronous one named MsmqLogDistributionStrategy. The InProcLogDistributionStrategy ClassThe InProcLogDistributionStrategy class is a thin wrapper around the LogDistributor class. The LogDistributor class distributes the LogEntry to all Destinations for which it has been configured. As the name implies, this all occurs in-process. The InProcLogDistributionStrategy class just creates a new instance of the LogDistributor class and calls the LogDistributor's ProcessLog method. MsmqLogDistributionStrategyThe Logging and Instrumentation Application Block is also able to send messages asynchronously. The MsmqDistributionStrategy is the Logging and Instrumentation Application Block's solution for sending messages asynchronously. The MsmqDistributionStrategy serializes a received LogEntry message and stores it in a Microsoft Message Queuing (MSMQ) queue according to the QueuePath for which it is configured. At this point, an MsmqLogDistributor class is responsible for reading the LogEntries from the queue and distributing them to all Destinations for which it has been configured. Whether an application is configured to use the InProcLogDistributionStrategy or the MsmqLogDistributionStrategy, the important concept to recognize is that both are responsible for getting the messages from the application that creates a LogEntry to a centralized distributor for all LogEntries. The objects covered up to this point are responsible for creating the message, determining whether the message should be sent, and publishing the message to a centralized distributor. They all run in an application's AppDomain, and from the Logging and Instrumentation Application Block's point of view they are considered to be the client side of logging. The important point is that the publisher of the messagethat is, the client that creates the LogEntryis completely decoupled from any Destinations that have been configured to receive the message. It is the centralized distributor's responsibility to determine all the Destinations that need the message. This is considered to be the distributor side of logging. In fact, if desired, the distributor can be deployed to run on a completely separate process from the client application. That is exactly how the MsmqLogDistributor works. If you're not very familiar with message-based design patterns (www.integrationpatterns.com is a great resource), perhaps a "real-world" example would help to clarify the concept. Think of this design working the same way that a beverage distributor works. A beverage manufacturer makes the product and packages it for delivery. However, the manufacturer does not deliver the product to every bar and restaurant that wants it. This would be very inefficient. Instead, it sends the product to beverage distributors, who then figure out how much and which type of product goes to each restaurant and bar and to deliver it there. Think of the LogWriter as the beverage manufacturer, the LogEntry as the product, the Distributors as the beverage distributor, and the Sinks (discussed later in this chapter) as the restaurants and bars that want the product. LogDistributorThe LogDistributor is a base class that represents the centralized distributor. It combines its configuration information with the value of a LogEntry's Category to determine all the Destinations to which a LogEntry should be sent. A Destination combines a Sink, which defines the data source to which a message can be persisted (e.g., e-mail, database, file, MSMQ, WMI), with a Formatter that defines how the message will look and what data it will contain. For every Destination, the LogDistributor performs four tasks.
The Sink then takes care of writing the message for its specific protocol. A high-level overview of this process was illustrated earlier in this chapter in Figure 6.2. DistributorServiceThat all works great if the distribution strategy is the InProcLogDistributionStrategy and the LogDistributor is called directly. However, for asynchronous messaging with the MsmqDistributionStrategy, the LogDistributor never gets called. After the MsmqDistributionStrategy stores the LogEntry in the queue, something else needs to get the message from the queue to the LogDistributor. This function is fulfilled by the Distributor Service. The Distributor Service is a Windows Service that polls a message queue to determine if any messages need to be sent. This design completely decouples any client that publishes messages from the "hub" that distributes the messages. The Distributor Service can be replaced by a different mechanism for routing messages to their Sinks (e.g., the Microsoft BizTalk Server), and none of the client applications will be any the wiser. Similarly, the Distributor Service is completely agnostic as to any changes made by client applications. As long as they still publish the messages to the message queue in the same way, the Distributor Service is happy. Figure 6.7 illustrates the design for asynchronous publishing of LogEntry messages and the resultant decoupling between the client applications and the Distributor Service. Figure 6.7. MsmqLogDistributionStrategy and the Distributor Service The Distributor Service, as shown in Figure 6.7, is really comprised of three separate classes. The first is the actual Windows Service, which is named DistributorService. This is the controlling member of the trio; it controls what occurs when the service is started, paused, or stopped. When the service is initialized, the DistributorService uses the information that is read from configuration to create a new instance of the MsmqListener class. When the DistributorService is started, the DistributorService tells the MsmqListener instance to start polling for messages from the configured MSMQ queue; on pause and stop it notifies the MsmqListener that it should stop polling for new messages. Figure 6.8 provides a closer look at the classes that are involved in the Distributor Service. Figure 6.8. A Closer Look at the Distributor Service MsmqListenerThe MsmqListener controls the polling of the queue for which the DistributorService is configured. When the MsmqListener is created, it creates an instance of the MsmqLogDistributor. When the MsmqListener is started, it creates a new Timer and EventHandler that instructs the MsmqLogDistributor to check for new messages in the queue. When it is stopped, the MsmqLogDistributor is "wound down" so that any messages already queued up are allowed to complete their process, and then the MsmqLogDistributor is no longer instructed to look for new messages. MsmqLogDistributorThe MsmqLogDistributor is a subclass of the LogDistributor class. It represents the centralized distributor for asynchronous log distribution. When the MsmqListener notifies this class to check the queue for messages, the MsmqLogDistributor loops through all LogEntry messages that exist in the queue, deserializes them, and calls the base LogDistributor's ProcessLog method. ProcessLog then performs the four tasks outlined previously to format and route the LogEntry to every Destination for which it has been configured. Custom Distribution StrategyIt is rare that you should ever have to write a custom distribution strategy or distributor. However, some exceptional situations exist where one may be needed. For example, some companies refuse to use MSMQ. Sometimes they just don't want it to exist on client machines; other times it is banned from server applications too. Many times this is more due to corporate governance policy than any technical reason. For example, it is not uncommon for a company to "standardize" on a queuing product like IBM MQ Series. Any solution that leverages a queuing product other than this is not in line with corporate governance policies. Therefore, leveraging a technology like MSMQ in these organizations becomes a difficult political battle at best. On the flipside, however, most corporations use some form of relational database in their applications. Thus, an alternative asynchronous distribution strategy that might appeal to corporations that don't promote the use of MSMQ might be one that leverages a relational database instead. In this way, a company can still reap the asynchronous logging benefits of the Logging and Instrumentation Application Block without sacrificing adherence to governance policies. Fortunately, the Logging and Instrumentation Application Block provides an extension point for adding custom distribution strategies. Unfortunately, creating a custom, asynchronous, distribution strategy is probably one of the more complex types of extensions to undertake with Enterprise Library. This is because both a custom distribution strategy and a custom Distributor Service need to be developed. The custom Distributor Service is especially interesting. The following steps will walk you through creating a custom asynchronous distribution strategy and distributor. (The complete code sample is on the book's Web site.) This exercise is divided into two steps: the client (distribution strategy) and the distributor. Creating the distribution strategy is the more straightforward part of this exercise. It isn't much different than any of the other extensions that have been shown in this book. To create a custom asynchronous distribution strategy, do the following three steps.
After the runtime and design-time classes have been created and the assemblies have been deployed properly, you can use the Enterprise Library Configuration Tool to choose a Database Distribution strategy as easily as the In-Process or MSMQ Distribution strategies. Leveraging this as the distribution strategy will result in LogEntries stored in the database instead of being sent directly to the LogDistributor or stored in an MSMQ queue. Figure 6.9 illustrates how the Database Distribution strategy can be added to an application's configuration as easily as any of the ones that ship with the Logging and Instrumentation Application Block. Figure 6.9. Selecting the Database Distribution Strategy But creating the distribution strategy is only half the battle. If a distributor doesn't exist that will read the LogEntries from the database and forward them to the appropriate Destination, the LogEntries will remain "in limbo" in the database. A custom Distributor Service must be created to fit this purpose. Extending Enterprise Library with a custom Distributor Service is a little unorthodox from the way all other extensions are created. This is primarily because the MsmqLogDistributor cannot be used as a viable model to emulate because its configuration information is retrieved through a specific property in the DistributorSettings class. The DistributorService property of the DistributorSettings class returns an instance of the MsmqDistributorServiceData class. If instead a DistributorServiceData class existed that was returned from this property and served as the base class not only for the MsmqDistributorServiceData class but also for any custom Distributor Service data classes, then this model could be reused. But, alas, it doesn't exist, and any custom Distributors will not have the advantage of using this property in DistributorSettings. Therefore, the same design cannot be used. As it turns out, though, there is another option. Keep in mind that the distribution strategy is completely decoupled from the distributor. Although both are needed for a LogEntry to make its way to its final Destination, the distributor does not need to know anything at all about the distribution strategy. In fact, in many ways, a Distributor Service can be thought of as just another application that uses the configuration features in Enterprise Library. A Distributor Service needs to read and write its own configuration information in addition to leveraging the available configuration information about the Sinks to which it needs to send the LogEntries. Therefore, I have implemented the Database Distributor Service in such a way that it uses its own configuration information instead of having it exist in the configuration information for the Logging and Instrumentation Application Block. As luck would have it, I understand that the MsmqLogDistributor has been refactored in a similar way for the next version of Enterprise Library. So, the following three steps were taken to create a custom Distributor Service.
RoutingA Destination is comprised of two components: a Sink and a Formatter. The Sink signifies the store where a LogEntry will be routed, and the Formatter is used to transform the LogEntry into its final format. Many Destinations can exist for each Category that is defined in a Logging and Instrumentation Block's distributor settings. SinksA Sink represents the final resting place for a LogEntry. In many applications this may be the Event Log, a text file, or a database. It is also very common that LogEntries of certain Categories result in both an e-mail message and an entry into one of these data stores. In that case, two or more Logging Sinks could be set up as separate Destinations for a single Category. Each type of Logging Sink is responsible for saving the LogEntry into the specific data store for which it has been created. If you are familiar with integration products like Microsoft BizTalk Server, you will be familiar with this concept. In BizTalk terms, Sinks are analogous to Adapters. The Distributor acts as the messaging hub and routes the messages to all Sinks that "subscribe" to messages of certain Categories. Enterprise Library ships with six Logging Sinks, and it provides an extension point for creating new ones. The six Sinks that come out of the box are the EventLogSink, FlatFileSink, MsmqSink, WMILogSink, EmailSink, and DatabaseSink. All these Sinks derive from an abstract base class named LogSink. Figure 6.11 depicts this class hierarchy. Figure 6.11. LogSinks in Enterprise Library ILogSink and LogSink.The LogDistributor doesn't know anything about any of the specific LogSinks that are available. Instead, it only knows that it may be configured to send LogEntries to many classes that have implemented the ILogSink interface. Therefore, new LogSinks can be created without any change to the distributor that sends the messages to the Sinks. The ILogSink interface only contains one method and one property. The single method it defines is SendMessage(LogEntry). This is used for the LogDistributor to send the LogEntry to the Sink. The single property is an accessor for getting and setting the Formatter that will be used to format the LogEntry. This makes it easy for the LogDistributor to format and distribute the LogEntries it has received. It simply loops through all the Destinations for the Category that is equal to the LogEntry's Category property, sets the Formatter, and sends the message. The code in Listing 6.15 is at the heart of the LogDistributor's DistributeLogEntry method. Listing 6.15. How the LogDistributor Sends LogEntries to Sinks
The LogSink class is an abstract base class that implements the ILogSink interface. In addition to the public SendMessage method and Formatter property, the LogSink class contains the protected methods listed in Table 6.6.
The SendMessage method is implemented at this base class and simply calls the PrepareMessage and SendMessageCore methods. By default, the PrepareMessage method will call the AddActivityIdToLogEntry method. If a TRacer is being used, this method adds the TRacer's CurrentActivityId to the LogEntry's ExtendedProperties. The tracer object will be covered later in this chapter. The Formatter property is also implemented in this base class. The LogSink class will return the Formatter that has been configured for the specific Destination. If no Formatter has been configured, then the TextFormatter will be returned. Formatters are covered in the next section. The abstract LogSink class makes it easier to create Sinks, because the only thing that needs to be implemented in a derived class is the SendMessageCore method. This method should determine how to store the LogEntry in the data store that the specific LogSink represents. DatabaseSinkThe DatabaseSink is a great example of this; it is a concrete class that overrides the SendMessageCore method to store messages in a relation database. The DatabaseSink stores LogEntries in a database by executing a stored procedure. Its implementation of the SendMessageCore method calls a private method to execute a stored procedure against the database for which it was configured. The formatted LogEntry and many of its propertieslike Title, Category, Severity, and TimeStampare passed in as separate parameters to the stored procedure. Once the stored procedure has successfully run, the LogEntry rests in the database. EmailSinkThe EmailSink's implementation of the SendMessageCore method leverages some private functions and an internal class to create and format an e-mail message[3] from the data contained in the LogEntry class. It uses its configuration information to populate a list of recipient e-mail addresses, the sender's e-mail address, a subject line prefix, and a subject line suffix. It then sends the e-mail message to the SMTP server for which it was configured.
EventLogSinkThe SendMessageCore method for the EventLogSink creates an instance of a System.Diagnostics.EventLog object for the event log and event source that it reads from its configuration data. It then formats the LogEntry and stores the LogEntry in the Windows Event Log by calling the System.Diagnostics.EventLog's WriteEntry method. FlatFileSinkThe SendMessageCore method for the FlatFileSink uses configuration information about the name of the file, header text to place at the beginning of a LogEntry, and footer text to place immediately after a LogEntry in order to write a LogEntry to a flat file. The SendMessageCore method calls a private WriteMessageToFile method that creates the directory for the file if it doesn't exist and writes the header (if configured), LogEntry, and footer (if configured) to the flat file. MsmqSinkThe MsmqSink writes a LogEntry to a Microsoft Message Queue. Its SendMessageCore method for the MsmqSink creates an instance of a System.Messaging.MessageQueue from the QueuePath that it reads from configuration. It formats the LogEntry and sets this as the body of a new System.Messaging.Message. It sets the message label to be the title of the LogEntry and the message priority equal to the priority of the LogEntry. Finally, it sets the appropriate value for MessageQueueTransactionType based upon whether the message queue is transactional and sends this new message to the MessageQueue. WMILogSink.The SendMessageCore method for the WMILogSink fires a LoggingWMISinkEvent with the LogEntry as the Eventdata. Because the LogEntry is attributed as an InstrumentationClass of InstrumentType.Event, a LogEntry or any subclass thereof can be published proactively to any WMI consumer that has subscribed to it. The only additional step that is required for custom LogEntry classes is to register the class schema with WMI. For example, the WSILogEntry class shown in Listing 6.10 can be registered with WMI by running installutil.exe against its assembly. Once this has been completed, a WMI consumer can be created that listens for a WMILogEntry and can take appropriate actions once one has been received. Listing 6.16 sets a WMI consumer up so that it will asynchronously "listen" for the WSILogEntry event data. When a WSILogEntry is received, the watcher_EventArrived delegate will be called. Listing 6.16. Listening for a WSILogEntry Event
Creating a Custom Logging SinkThe Sinks that ship with Enterprise Library represent a pretty good suite of logging Destinations. Sometimes, however, the provided Sinks just won't fit every need for every company. That's okay, though. Creating a custom Logging Sink is straightforward, and there are already quite a few that have been created and can be found at gotdotnet.com. [4]
The tasks needed to create a custom Sink are no different than the tasks that were needed to complete the Sinks that ship with Enterprise Library. A class must be derived from the LogSink base class and the SendMessageCore function must be overridden to accomplish the specific tasks needed for that LogSink. Enterprise Library ships with a Quick Start sample for creating a custom Sink. The Quick Start outlines the steps needed to create the DebugSink, a Logging Sink that will send the debugging information to Visual Studio's Output window. The following are the steps to create this custom Sink (as taken from the Enterprise Library Quick Start documentation).
Listing 6.17. Creating a Custom DebugSink Class
That's really all there is to it. To use new Logging Sink, it needs to be configured in an application as a custom Sink and the DebugSink type information needs to be specified for the TypeName property. Then the logging Categories simply need to be modified to use this new Sink. This is a great example for using the out-of-the-box features for a custom Sink because it does not need to read any information in from configuration. However, it isn't hard to imagine that a custom Sink would need to leverage configuration information in the same way that the Sinks that ship with Enterprise Library do. There are two different ways to support this if a custom Sink had this requirement. A custom Sink can use its Attributes NameValueItemCollection to read in and use additional information from configuration. For example, if it were desirable to have a header and footer available to surround the debugging information (like the FlatFileSink), this information could be added to the custom Sink by adding two new items to the custom Sink's Attributes collection. Figure 6.12 shows how to use the Attributes collection to add configuration data for a custom Sink. Figure 6.12. Adding Attributes to a Custom Sink The custom Sink would need to use the instance of the CustomSinkData object that can be obtained in the Initialize method and used in the SendMessageCore. Listing 6.18 demonstrates this. Listing 6.18. Adding Code to the Initialize Method to Read Configuration Data from Attributes
This will work effectively and is very convenient from the perspective that it incurs very little development cost. A more elegant but slightly more costly approach is to provide a design-time interface for the DebugSink so the configuration information can be checked at design-time instead of runtime. The first step to creating a design-time interface for the DebugSink is the creation of a new class that contains the runtime configuration data specific for the DebugSink class. I'll name this class DebugSinkData. It is very similar to the FlatFileSinkData except there is no need for a filename variable or property. For instructions on how to accomplish this, see Chapter 1 and the source code for this chapter on the book's Web site. Secondly, a design-time node and configuration manager need to be created to allow an end user to configure an application to use the DebugSink. For instructions on how to accomplish this, see Chapter 2 and this chapter's accompanying source code. Lastly, the DebugSink needs to use the DebugSinkData instead of the CustomSinkData. Listing 6.19 shows the changes that need to occur in the DebugSink's SendMessageCore method. Listing 6.19. Changing the DebugSink's Initialize Method to use DebugSinkData
When these three steps have been completed, the DebugSink can be added as easily as any of the Sinks that ship with Enterprise Library. Figure 6.13 shows how to add the DebugSink to an application's configuration information. Figure 6.13. Configuring the DebugSink FormattersOne half of a Destination's purpose is to facilitate the routing of the LogEntry to the appropriate endpoint. That is the Sink's role. The other half of a Destination's job is to format the LogEntry into its appropriate representation. This is the role of the Formatter. The Logging and Instrumentation Application Block ships with a single Formatter, the TextFormatter. This Formatter, as well as any custom Formatters that are created, must implement the IFormatter interface. Figure 6.14 illustrates this relationship, as well as some of the other classes that are used in the formatting process. Figure 6.14. Classes Involved in Formatting ILogFormatterThe LogDistributor reads configuration data to determine which instance of a class that implements the ILogFormatter interface must be created to use for transforming a LogEntry. The single method for this interface, Format(LogEntry log), returns a string. Thus, any concrete Formatter must implement the Format method and return the LogEntry as a string. TextFormatterThe TextFormatter combines a template and tokens to create a formatted string. The template is a string that represents the final text that the Format method will return plus placeholders (aka tokens) that represent specific values that will be inserted at runtime. For example, a simple template that returns a Message, EventId, TimeStamp, and Severity might look like:
This would return:
The TextFormatter class contains static string constants; each one represents a LogEntry property like Message, EventId, TimeStamp, and Severity. The TextFormatter also contains strings that represent a newline and tab character. The template is stored with the rest of an application's distributor setting configuration information. A Template Editor ships with Enterprise Library that makes it easy to create and modify Formatter templates. You access the Template Editor by clicking the ellipses button for a TextFormatter's Template property in the Enterprise Library Configuration Tool. When the TextFormatter is initialized, the configuration data is read and the template is "registered" with the TextFormatter. Figure 6.15 shows the Template Editor. Figure 6.15. The Template Editor Registering the template with the Formatter means that the text for the template is used to create an internal StringBuilder object, and an ArrayList of TokenFunctions is created. The first thing the Format method does is to replace all the tokens in the template with the actual data contained in the LogEntry object. For example, the {message} token is replaced with the value of the LogEntry.Message property, the {eventid} token is replaced with the value of the LogEntry.EventId property, and so on. Then, the Format method is called for each TokenFunction. TokenFunction.You can think of a TokenFunction as a token that requires something other than simply being replaced with a LogEntry property. It requires some additional formatting to take place. For example, the timestamp for a LogEntry can be represented using many different date/time formats; two options are MM-dd-yyyy and dd-MM-yyyy. By leveraging a TokenFunction that supports this capability, this level of formatting can be supported. An abstract TokenFunction class exists that is used to set up these special formatting needs. Table 6.7 lists the constructs used by a TokenFunction class to perform the necessary formatting.
To achieve these special formatting needs, a class must derive from the abstract TokenFunction class. The abstract TokenFunction class has protected constructors that allow the start and end delimiters to be set. The TokenFunction class contains a virtual Format method that searches the template for all instances of the TokenToReplace and replaces them with formatted values. Finally, the TokenFunction class contains one abstract method named FormatToken. This is the only method that must be implemented by any derived class and is the method that takes the TokenToReplace and formats the LogEntry data into its final form. Figure 6.14 shows the TokenFunction classes that ship with Enterprise Library: TimeStampToken, KeyValueToken, and DictionaryToken. TimeStampToken.The TimeStampToken class lets an end user dictate the date/time representation for the LogEntry's TimeStamp property. For example, to format a timestamp using a date/time format of MM-dd-yyyy, the token {timestamp(MM-dd-yyyy)} can be used. The TimeStamp-Token performs log.TimeStamp.ToString(tokenTemplate, Culture-Info.CurrentCulture)on the InnerTemplate (aka tokenTemplate) that is passed to the FormatToken method. Because the TimeStampToken does not override the default behavior for InnerTemplate, which is simply the text between the start and end delimiters, many different date/time formats can be used in a single template. As the Format method loops through the template replacing TimeStampTokens, it will pass a different templateToken to the FormatToken method each time. For example, suppose a template consisted of: In the United States, this message was logged as {timestamp(MM-dd-yyyy)}, but in the United Kingdom it was logged as {timestamp(dd-MM-yyyy)}The first call to the FormatToken method would use MM-dd-yyyy as the templateToken and the second call would use dd-MM-yyyy. This would result in:
KeyValueToken.The keyValueToken class lets an end user create a template that uses a specific value in a LogEntry's ExtendedProperties dictionary object. The KeyValueToken uses the templateToken that is passed to the FormatToken method as the key that needs to be located in the ExtendedProperties dictionary object. If the key does not exist in ExtendedProperties, an empty string is returned. For example, let's say that a LogEntry's ExtendedProperties dictionary was populated with the results of the ManagedSecurityContextInformationProvider.PopulateDictionary method. This would populate the ExtendedProperties dictionary with key/value pairs where the keys are AuthenticationType, IdentityName, and IsAuthenticated. This information can be used in the template by leveraging the KeyValueToken class. So, a template that consists of the string: This message was logged by {keyvalue(IdentityName)}.{newline}will return This message was logged by AppDomain\TestUser. when the name of the user logged into the application is TestUser in the AppDomain domain. DictionaryToken.The DictionaryToken class iterates over all the key/value pairs in a LogEntry's ExtendedProperties dictionary and displays the data for both the keys and the values. The start delimiter for the DictionaryToken is {dictionary( and the tokenTemplate that is passed to the DictionaryToken's FormatToken method contains an additional template that dictates the string representation for these key/value pairs. It substitutes the {key} token with the name of the key and substitutes the {value} token with the value of the item. Let's use the same example as with the KeyValueToken: a LogEntry's ExtendedProperties dictionary is populated with the results of the ManagedSecurityContextInformationProvider.PopulateDictionary method. However, let's add the DictionaryToken to the template to change it to: This message was logged by {keyvalue(IdentityName)}.{newline}. Extended Properties are: {dictionary({key} has a value of {value}.{newline})}This will return a formatted LogEntry of: This message was logged by AppDomain\TestUser. Extended Properties are: IdentityName has a value of AppDomain\TestUser. AuthenticationType has a value of NTLM. IsAuthenticated has a value of True. Because the regular tokens get replaced before any TokenFunctions, the {newline} token was replaced with a newline character before the DictionaryToken was replaced. Similarly, if the template for the DictionaryToken included other tokens, like the {message} or {severity}, those would also get replaced before any TokenFunction replacement. Revisiting the DebugSink (a Custom Sink)Upon examining the output that is produced by the DebugSink, it becomes apparent that the output that is produced is not the string that is expected as a result of using the TextFormatter. Instead, it is a string with only the EventId and the message. This is because the code shown so far for the DebugSink does not take into account the Formatter that may have been set for it. Instead, it simply wrote the EventId and Message. For a Logging Sink and Formatter to work together properly, the Logging Sink must use the Formatter in its SendMessageCore method. Thus, changing the line of code in the DebugSink SendMessageCore function from this: Diagnostics.Debug.WriteLine(SR.DebugSinkMessage(logEntry.EventId,logEntry.Message)) to this: Diagnostics.Debug.WriteLine(FormatEntry(logEntry) results in the expected formatted output. Creating a Custom Token and FormatterWhen I provided the code sample for the custom ExtraInformationProvider in Listing 6.7, I left out one step. For this custom ExtraInformationProvider to work, both a custom TokenFunction and Formatter are needed. This is because the data that is replacing the token actually contains the token that is being replaced. Because the TextFormatter loops through the template and replaces the tokens with the entries in the dictionary, using the DictionaryToken with TextFormatter results in an infinite loop when replacing the tokens. To better demonstrate the scenario, let's concentrate on the token and the data. The template contains the DictionaryToken as {dictionary(Key: {key}{tab}{tab}Value: {value}. Because the actual configuration data that contains the template is being logged, the data that gets logged will also contain {dictionary(Key: {key}{tab}{tab}Value: {value}. After the first instance of this token is replaced, the code looks for the next instance of the token. If the starting position to search for the token is before the start of the data that just replaced the token, the token will be found in the newly entered data and the configuration data will be replaced here again. This process will continue infinitely (or until the machine runs out of memory). The DictionaryToken's Format method works this way. So, to log the application blocks' configuration data for an application, I created a new token named ELDictionaryToken that is a subclass of DictionaryToken and overrides the Format method, so the start position for the next token search is after the last character of the newly entered data. Because the TextFormatter is coded to just register the TimeStampToken, KeyValueToken, and DictionaryToken, a new custom Formatter needed to be created that registers the ELDictionaryToken instead of the DictionaryToken. Therefore, I created a custom Formatter that derives from the TextFormatter to suit this purpose. Listing 6.20 shows the ELDictionaryToken's Format method. Listing 6.20. ELDictionaryToken's Format Method
The only differences between the new TextFormatterWithELDictionary that I created and the TextFormatter that ships with Enterprise Library are in the Initialize and RegisterTokenFunctions methods. Listing 6.21 shows these methods. Listing 6.21. TextFormatterWithELDictionary
The normal procedure for adding a design-time interface on top of the TextFormatterWithELDictionary can be taken to configure it through the Enterprise Library Configuration Tool (see Chapter 2). The complete source code is on the book's Web site. TracingTracing is considered to be relatedbut differentfrom logging in the Logging and Instrumentation Application Block. Whereas logging is the act of publishing a LogEntry message to one or more endpoints, tracing is concerned with "telling a story" by logging and correlating multiple messages that occur in a particular activity in an application. Examples help to differentiate the two. Let's say that a Web application exists for taking online orders. It would be typical to "log" events like receiving a request via a Web service or storing data in a database. It is also typical to "trace" the activity of a process throughout the entire application from start to finish. That is, it wouldn't be atypical to trace when the UI process started, when the business process started, when the data process started and finished, when the business process finished, and, finally, when the UI process finished. This would represent an entire activity in an application with several subactivities along the way. The "logs" occur in the tracing for this process. Figure 6.16 illustrates this scenario. Figure 6.16. Tracing and Logging in an Application The design goal for the Logging and Instrumentation Application Block is to make it as easy to trace processes in an application as it is to log when specific events occur. To this end, the tracer service façade exists. tracer is the object that is used to trace processes in an application. The public interface that is exposed to accomplish this is simple: constructors are used to create and start the tracing process, and a Dispose method is exposed to clean up and end the tracing process. When an instance of a TRacer object is created, a Start Trace: Activity '<ActivityId>' in method '<MethodName>' at <NumberOfTicks> ticks message is logged. The ActivityId is used to correlate the log messages, the MethodName is the name of the method where this tracer was created, and the NumberOfTicks represents the time this instance was created as obtained from the native Win32 QueryPerformanceCounter function.[5]
When the Dispose method is called, an End Trace: Activity '<ActivityId>' in method '<MethodName>' at <NumberOfTicks> ticks (elapsed time: <Seconds> seconds) message is logged. If using VB.NET, the Dispose method must be explicitly called to release the TRacer object and generate the End Trace message. This happens automatically when using the using keyword in C#. Figure 6.17 depicts how the tracer class contains a constructor, Dispose method, and four properties. Figure 6.17. The TRacer Class For example, in Figure 6.16 the first TRacer object was created in the UI layer. This represents the outer Trace for all other Traces that may occur in this activity. The code to perform this Trace could be as simple as that in Listing 6.22. Listing 6.22. Creating the Trace in the UI Layer
The two log messages that result from just using the tracer in this way are shown in Listing 6.23. Listing 6.23. Results from Using the tracer in the UI Layer
Because the ActivityId is not specified in the tracer's constructor, its value is automatically set equal to a new Guid. Activity IdentifiersActivityIds are used to correlate different trace messages that occur in a single activity in an application. The previous scenario illustrated the entire process of entering data into a UI form, sending it through the different layers in the application, and returning the results in the UI. This can be thought of as a single activity, and showed how a unique activity identifier can be automatically generated and used to correlate all traces and logs that occur in this activity. Sometimes, however, it may be beneficial to override a particular activity identifier for some of the messages logged during a component's execution. Nonetheless, callers to this component shouldn't have to be concerned with whether the activity identifier is being changed or not. Therefore, the tracer object uses an Activity Identifier Stack to ensure that the activity identifier returned from any component has the same value that it had before the component was called. Each time a new tracer object is created, the application block pushes an activity identifier to the top of the stack. When Dispose is called, the activity identifier is popped from the stack. The value for the activity identifier is determined according to the following rules.
Listing 6.25. Nested Tracers using the Same ActivityId
Listing 6.26 shows how all log messages have the same activity identifier. Listing 6.26. Results of Nested Tracers with the Same ActivityId
This is true whether the nesting occurs in the same method or not. For example, the same result would occur if the second tracer object was created in a method in a business object instead of in the UIButton_Click method. The only difference in the log would be the value for the MethodName that is displayed as the Start and End Log messages. In other words, the same result can be achieved from the code shown in Listing 6.27. Listing 6.27. Nested Traces in Multiple Methods
The tracer object exposes two static properties that can help you determine the activity identifiers that are in use. The CurrentActivityId property returns the current activity identifier, and the RootActivityId property returns the root (or outermost) activity identifier. Category StackIn addition to maintaining a stack for the activity identifiers, the tracer object maintains a stack for the Categories. Since the Category is a required argument in the tracer's constructor, it must always be supplied; therefore, the Category is always pushed onto the stack when the tracer is created. When the tracer is disposed, the Category is always popped from the stack. It can be useful for you to ascertain the current and root Categories that exist when tracing an activity. For that reason, the tracer object exposes two static properties similar to the properties exposed for the ActivityId stack. The CurrentCategory property returns the current Category, and the RootCategory property returns the root (or outermost) Category that was used when the initial Tracer was created. Logging While TracingAny logging that is performed in the scope of a tracer object will automatically have the value of the tracer.CurrentActivityId added to its ExtendedProperties with a key of tracerActivityId. This ActivityId is added by the abstract base LogSink class when it prepares the message to be sent. This occurs in the LogSink's virtual PrepareMessage method that is called right before SendMessageCore. This is an important point to understand if a custom Sink needs to be created that must perform some additional logic to prepare the message before calling SendMessageCore. This logic belongs in the PrepareMessage method; if this method is overridden, it is important to remember that either the base.PrepareMessage method or the AddActivityIdToLogEntry method should be called. Failure to do this will result in the absence of the ActivityId in a LogEntry's ExtendedProperties when logging in the scope of a Trace. All results from the code examples in this section resulted in the existence of this additional extended property. |
severity of {severity}. {newline}
EAN: 2147483647
Pages: 103