Overview of XQuiSoft Logging using the provider pattern (open source)

• Download demo project - 548 Kb

Introduction:

XQuiSoft Logging is an open source component for logging support in .net applications. It is part of the XQuiSoft application framework, which is entirely open source. It goes beyond what can be done in the built in .net framework System.Diagnostics.Trace and System.Web.TraceContext. You can get the latest version of the project and unit testing (demo) code at

http://sourceforge.net/projects/xqs-logging

This logging component has a dependency on two other open source projects in the xquisoft framework.  The xquisoft provider component is the first.  It is basically an implementation of the provider pattern for the 1.1 framework similar to that in the 2.0 framework.  The second is the xquisoft data component, used for database abstraction.  This component is only required if you use the DbLogProvider.  These two open source projects can be found at:

http://sourceforge.net/projects/xqs-provider
http://sourceforge.net/projects/xqs-data

The documentation is available on XQuiSoft Developer Network (xqsdn).  Use the index page to find help on any of the class names highlighted in the text below.  Not all topics covered in xqsdn documentation are open source, however all referenced by this article and used in the logging component are open source.

http://www.xquisoft.com/xqsdn/documentation/index.html
http://www.xquisoft.com/xqsdn/documentation/xquisoft.logging.html
http://www.xquisoft.com/xqsdn/documentation/xquisoft.logging.data.html

Demo Code Notice:

When you unzip the demo project you'll need to do one of two things.

• move the web projects into inetpub\wwwroot.  And copy the solution and resources folder to C:\SomeFolder\
• Update the solution file to the correct paths for each project and create virtual folders of the project names that point to the projects.  Then update all the logging package references to the new location of the resources folder.

On my test machine I had the solution in a working folder on my C:\ drive which I use for all projects.  Then when I added the web projects they were added to inetpub\wwwroot.  That made it a little hard to zip the solution.

Basic Features:

Ease of use: All you have to do to write a message to the log is call a single static method on the Log [^] class. There are various overloads of the log methods available for specifying more or less information. When writing a message you do not have to create a logger instance, or pick a particular logger to write to. Literally, you simply type "Log.Write(...);", where ... is the message and any other details you feel like adding.

Extensibility: The logging component is based on the provider pattern. This means that the Log [^] class delegates the actual writing call to one or more configured providers (listeners) that derive from the base LogProvider [^] class. Each implementation provider defines where log events are written, if they are buffered, or any other custom configuration options required for writing to a given datasource. If you have a custom datastore, you can create your own logging provider and configure it for use in your application. Then any component written by another component author automatically uses your logging provider (assuming they write log messages :).

Multiple configuration methods: You can configure your application to use logging in two ways. The first is to create a configuration section in your application configuration file. The section would define the logger(s) to use, and any filters to apply to the logger(s). The second method is to initialize a new logger and add it to the Log's provider collection at run time. you can also configure the log provider at any point in the application life cycle, or remove a logger from the main Log.Providers [^] collection. The typical scenario is to use a configuration file. You can see examples in the test applications available with the download. Also the documentation includes sample application configuration sections. See the help on each log provider for details on how to configure it. Also the help for LogConfigurationHandler [^] shows how multiple log providers can be composed.

Stability: The Log [^] class itself will never throw an exception to a component trying to write a log event. Exceptions within the logging component are handled by a backup logger of your choice. each logger can have a different backup logger, and backup loggers can be setup in a chain. If there is no backup logger, or the backup logger(s) also fail then the logging error is ignored.

Flexibly filtering: The filtering is also based on the provider pattern. There is a base FilterManager [^] class with a providers collection where each provider derives from FilterProvider. [^] Each filter provider is accessed by a key (the filter's name). There are powerful filters built in, but you can create your own filter providers. Filters can be combined into more complex filters with the built in "Or" and "And" filters. Each log provider can be configured to use the same or different filter providers.

Composition: Logs can be configured to have child loggers. For example the BufferedLogProvider [^] holds all the messages in a memory buffer. When it is time to flush the buffer it sends those messages to the constituent log provider(s).  Each of those can either log it, or attempt to filter each message further before logging. Not all loggers support composition, they only do where it makes sense. See the help for each log provider type for details. You can configure any other log provider as a constituent of a BufferedLogProvider [^], so in short all log provider destinations can be buffered.

Event makeup: A single log event consists of a Level, Source, Category, Message, Details, and Timestamp. The level is an integer scale of importance. There are built in levels named as Error(256), Warning(512), Info(1024), and Verbose(2048). You can use those levels or make up custom levels in between those levels. The source is who invoke the message. Category is what it seems, a way for the source to categorize one message over another. message and details are informational fields of differing length. Note, filters can be based on any of these fields.

Performant: The framework itself does not slow down an application to any noticable effect. The overhead is in the required operations to write to the destination datasource. For instance, Writing to a file has the overhead of opening and closing a file. However, with a combination of the BufferedLogProvider [^] and the FileLogProvider [^] this overhead only takes place at the configured time interval. See the performance test results, or run the tests yourself. The test code is available as a download with the article that compares XQuisoft Logging, log4net, enterprise library (logging), and nspring.

Built in LogProviders:

1. DebugLogProvider [^] - writes to System.Diagnostics.Trace and System.Web.TraceContext as applicable
2. ConsoleLogProvider [^] - writes to System.Console
3. EmailLogProvider ["http://www.xquisoft.com/xqsdn/documentation/XQuiSoft.Logging.emaillogprovider.html" target=_blank>^] - writes log messages to email. recommended as an exception provider only so as not to overflow an email box.
4. FileLogProvider [^] - writes log messages to a file. The filename can be formatted based on the event being logged. This is how you can accomplish a new log file every hour (or other interval).
5. BufferedLogProvider [^] - acts as shared buffer amoung one or more other log providers. This provider can have child logs. When the buffer hits the configured buffer size, all the buffered messages are sent to the child logs at once.
6. SessionLogProvider ["http://www.xquisoft.com/xqsdn/documentation/XQuiSoft.Logging.sessionlogprovider.html" target=_blank>^] - (web projects only) stores all the messages in the current users session. If an Error level event is logged, then the buffer is flushed to other provider(s) of choice. A max size can be configured (default 32) to prevent sessionState from becoming to large.
7. DbLogProvider [^] - Logs messages to any database that supports stored procedures.  It comes with install scripts for sql server.  This provider is defined in a separate assembly from the other build in log providers, and it has a dependency on XQuiSoft.Data component from the XQuiSoft framework.  You can find that on sourceforce too.  http://sourceforge.net/projects/xqs-data/   This component deserves it's own article.

If the FileLogProvider [^] is a child log of a BufferedLogProvider [^] or SessionLogProvider ["http://www.xquisoft.com/xqsdn/documentation/XQuiSoft.Logging.sessionlogprovider.html" target=_blank>^], then the output file is opened only once for the entire buffer of events, assuming each event goes to one file. The output loop only closes the file, and opens a new one between events when the next event has a different target file.  This would be the case when the target file varies based on the timestamp or other property of the event. See the unit test for an example, and the source for implementation details.

Built in Filters:

1. LevelFilter [^]. only accepts events at or below a given level.
2. ExpressionFilter [^].  Can filter on any one log event field. It matches on a regular expression. The unit test code for this filter contains examples.
3. AndFilter [^].  Allows grouping of other filters, such that each child filter must accept for the AndFilter to accept.
4. OrFilter [^].  Allows grouping of other filters, such that only one child filter must accept for the OrFilter to accept. Evaluation terminates at the first child filter to accept.

All filters can be configured to be either Inclusive [^] equal true or false. It is like having a ! (not) operator in front of the filter. You can combine as many levels nested as desired of OrFilter [^] and AndFilter [^] to get the desired result. All filters are added to the same FilterManager [^], each must have a unique name otherwise an exception is thrown when the duplicate named filter is added to the manager. See the unit tests for examples of each kind of filter in use.

Why use XQuiSoft Logging instead of log4net, Nspring, and enterprise library?

These other logging frameworks are satisfactory. If you are using one of these frameworks in an application you may not want to switch.  However, I belive that you write less code using the xquisoft logging component. So on your next project take the following into consideration. Here are a few points of differentiation that I have noticed.

If you find that any of this is incorrect, please let me know and I will correct the article.

Are the others hard to use? No. But they aren't all AS easy to use. Take for instance NSpring. I didn't see anywhere in NSpring that you can create a logging configuration. You also have to instantiate a logger in your application, open it, write to it, and then close it. Why do you have to do so much work? If you write a component for others to use, and you want to log something how do you know what your client(s) wants to log to? Do you have them pass a logger to you? That just sucks.

Logger log = Logger.CreateConsoleLogger();
log.Open();
log.Log("my message", "my category");
log.Close();

In log4Net, you apparently have two options. You either have to know the name of the destination logger, or you have to get it based on reflection.

ILog Log = LogManager.GetLogger("BufferingForwardingAppender");
Log.Debug("Test log message");

private static readonly ILog Log = 
LogManager.GetLogger( MethodBase.GetCurrentMethod().DeclaringType);
Log.Debug("Test log message"); 

In XQuiSoft you just need one line.  The Log class has all static methods, and each is delegated to the providers as configured.  Enterprise library is very similar in usage from your code.

XQuiSoft Logging:

Log.Write(Level.Info, "my category", "my message");
// 'Log.Info' is a constant integer value.

Logger.Write("Message To Log", "Category Name", 0);
// 0 is the message level, you can also use an enum 

All of these logging packages are extensible. They all give you an abstract base class to derive from. The base class offers overloads that call another abstract method overload that must be implemented in your custom provider. XQuiSoft refers to them as "providers", nspring refers to them as "loggers", log4net refers to them as "appenders", and enterprise library refers to them as "sinks".

Finally, I tested the relative performance of each logging package. I created a single solution. Each test was contained in it's own web project so that test results would not be affected by one log packages configuration and/or memory overhead. Each project contained a single web page that does not display anything, but the Page_Load method enters something into the log. Another web application that does nothing is also included as a baseline of maximum performance. Then I used Microsoft Application Center Test for load testing. I simulated 30 simultaneous browser connections, a 5 second warm up time, and a duration of 5 minutes. here are the results of each test, with the most performant at the top:

Oddly, the xquisoft file logger was the fastest possible way to log. The reason it is faster than the xquisoft console logger is that the console logger was not sent through a buffer. But I don't think buffering a write to the console would improve speed since each Console.Write does not open a resource, or if it did there is no way to request that it stays open between calls. I used a BufferedLogProvider [^] with an interval of 20 seconds that wrote to a FileLogProvider [^] when it was flushed. The file name for the file logger varied based on the a timestamp down to the minute (ie. FilePath="~\log\{Timestamp:yyyyMMdd-HHmm}-log.txt"). Therefore, some write (flush) operations included items in the buffer that went to two separate log files (ex. 20060419-1146-log.txt, and 20060419-1147-log.txt). When you look at the graph for the XQuiSoft file logger test you can see a dip in performance every 20 seconds when a write operation was occuring.

The log4net file logger actually was buffered, although it appeared as if it wasn't. I used a BufferingForwardingAppender with size 100, that wrote to a RollingFileAppender. So it should have tried to keep the file open for a series of 100 events at a time. however, when I look at the MACT test the graph does not show low points at a regular interval to indicate that the buffer worked that well.

I cannot explain how the nspring file logger was faster than both the nspring console logger and the log4net file logger. Overall the nspring loggers had very erractic performance levels according to the MACT test result graph. It may be because the nspring logger does not support configuration files, and I had to recreate a logger on each page_load. Much of the overhead can be attributed to not being able to cache instances of a logger between page calls. If anyone can update my test code with an improved usage of nspring, please let me know.

I did not run the performance tests the enterprise library for a few reasons. First, I couldn't get them to run. Apparently you can't just xcopy the ent lib dll's and use them. You have to install the performance counters. An error on the web page is related to performace counters, and not being able to open the registry. In order to disable them you have to edit and recompile the library! Why can't they just supply a config setting to not attempt writing to the performance counter? I didn't want to bother with all that. The second reason I didn't test it is because there are already performance comparisions between log4net and ent lib which show that ent lib is much slower than log4net. XQuiSoft Logging is faster than log4net, so that makes XQuiSoft Logging faster than ent lib.

Microsoft Enterprise Library Logging Block compared to Log4net follow up (Loren Halvorson)
http://weblogs.asp.net/lorenh/archive/2005/03/20/395289.aspx

Exception Handling:

As of June 12th a new version of the Logging component has been released.  The earlier version initialily took a different approach to exception handling.  First, I generally have two major rules in exeption handling

1) don't swallow and ignore exceptions!  Always report it either to a log, and/or to the application user.  The only 'exception' (pun intended) to this rule is if you can successfully mitigate the problem.  For instance, maybe you have fallback logic to try if the first method does not work.

2) Don't catch and propagate exceptions that you do not have explicit logic to handle.  No catch (Exception ex){}.  This rule applies to data and business layers in an application, and also to standalone components.  The only time you should catch Exception is in the Application_Exception or equivalent.  You catch it at this top level to prevent an all-out crash.  This handler usually log's the problem and displays a warning to the user.

In the logging component (pre 1.5) an exception in logging swallowed the exception if logging failed.  My reasoning was that a failure in logging should not crash your application.  The business layer exception that occured is really what you'll display to the user.

To handle exceptions in loggers the component has always supplied a property on the base LogProvider called ExceptionProviderName.  It determines the name of a backup logger to send exceptions from the main logger.  You can 'chain' failover loggers ending with a logger that should never fail, maybe the system log.  However, if the final logger failed, it was ignored.

I've re-considered this position to align with my exception handling rule #1.  Now the final logger in the chain will throw a LogException to the caller of the logging component.  However, if an attempt is made to log a LogException it is ignored, since if it was possible to ignore it would have been logged already.  This prevents an endless loop of exceptions being thrown.

If you still want to ignore logging exceptions you can.  Create a new LogProvider that does nothing, and make it the last logger in your exception chain.  Don't swallow LogExceptions in your app code.  That way you can configure the last log exception failover to be a DebugLogProvider and have the page output the fatal logging error without having to remove that exception swallow code..

Conclusion:

I've covered the basics features and usage of the XQuiSoft Logging component. I've also compared XQuiSoft Logging to the other major logging components / frameworks on the market. From what I have seen, XQuiSoft Logging is a much better component. But then again I am biased since I wrote XQuiSoft Logging. I would like to see others make a similar comparision and see what the results are?

If you already extensively use another logging component are are very happy with it, then keep using it. However, if you start a new project, consider the benefits of XQuiSoft Logging over the others. Evaluate it, and see if it fits into your toolbox.

History:

April 19, 2006: Initial submission of article.
April 20, 2006: Added link to comparison between log4net and entlib performance.  Also added links to the open source projects that are required by this logging component.

June 12, 2006: Added new exception handling policy. Updated to component version 1.5.5000.0.  Get it from source forge.  The sample code was not updated since no API changes were made.