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 from http://sourceforge.net/projects/xqs-logging.
This logging component used to have a dependency on two other open source projects in the xquisoft framework. These projects are all distributed together as of December 2010.
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 and later in this article. 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 LogConfiguration shows how multiple log providers can be composed.
Stability: The Log class itself generally does not 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 throw to the caller.
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 invoked 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 noticeable 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
DebugLogProvider - writes to System.Diagnostics.Trace and System.Web.TraceContext as applicable ConsoleLogProvider - writes to System.Console EmailLogProvider - writes log messages to email. Only recommended for error events requiring immediate attention. 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). RollingFileLogProvider - writes log messages to a rolling list of files. You configure how many files there are and how big each one gets. This is best when you want to log to disk but keep the disk space used at a given maximum amount and keep only the most recent log entries to help diagnose errors. BufferedLogProvider - acts as shared buffer among 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. SessionLogProvider - (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 too large. 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 built in log providers, and it has a dependency on XQuiSoft.Data component from the XQuiSoft Framework. You can find that on sourceforce too at http://sourceforge.net/projects/xqs-data/. This component is introduced in this article. NullLogProvider - Log messages are discarded. Put this as the ExceptionProviderName for your loggers if you want to ignore all exceptions during logging so that failures to log do not crash your application. If you use this and logging is misconfigured, you just won't see any logs written.
If the FileLogProvider is a child log of a BufferedLogProvider or SessionLogProvider, 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 or 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.
If the EmailLogProvider is a child log of a BufferedLogProvider or SessionLogProvider, then an email is generated only once for the entire buffer of events. Each event in the email will appear on a new line. The format of each event is customizable.
Built in Filters
LevelFilter - Only accepts events within a given level range. MaxLevel and MinLevel define the range. ExpressionFilter - Can filter on any one log event field. It matches on a regular expression. The unit test code for this filter contains examples. AndFilter - Allows grouping of other filters, such that each child filter must accept for the AndFilter to accept. The filter can be negated with the IsInclusive setting. 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. When IsInclusive is configured as false, only events that fail all child filters are accepted.
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.
Configuration
First, define the structure of the custom configuration section in the configSections as shown here. You can only have one configSections node, so merge the contents here with what you may have now.
<configSections>
<sectionGroup name="XQuiSoft.Logging">
<section name= "Log" type="XQuiSoft.Logging.LogConfiguration, XQuiSoft.Logging" />
<section name= "FilterManager" type="XQuiSoft.Logging.FilterConfiguration,
XQuiSoft.Logging" />
</sectionGroup>
</configSections>
Then you need to define your custom settings. Below is an example writing all log messages to a file, and errors to an email. All log messages are first sent to the buffer, which lets your application code continue to run. Then every 10 seconds, a background thread sends all buffered messages to the email logger and the file logger. The email logger sifts through the messages and if any are errors or warnings an email is sent to the developers. If they are all debug or info messages (normal operation) then no email is sent for that buffer. The file logger saves all the messages sent from the buffer to a file for the current day. Each day gets a different log file. If any errors occur in the email logger or the file logger, a log message is saved to another file. If the failover fails, then an application exception occurs. If this is a web application, Application_Error in global.ascx is fired.
As of the December 2010 release, the BufferedLogProvider will now send all buffered messages when a Log.Fail call is made. So on error, you will see the files on disk updated immediately and the email sent immediately.
<XQuiSoft.Logging>
<Log>
<providers>
<add name="BufferLogger" type="XQuiSoft.Logging.BufferedLogProvider,
XQuiSoft.Logging"
TargetProviderNames="FileLogger,EmailLogger" OutputInterval="10" />
<add name="EmailLogger" type="XQuiSoft.Logging.EmailLogProvider, XQuiSoft.Logging"
FromAddress=your-application@your-domain.com
ToAddresses="developers@your-domain.com"
ExceptionProviderName="Failover"
Subject="ERROR IN your application on server XYZ"
FilterName="Verbose" ActiveRoot="false"
ItemFormat="{Timestamp:yyyyMMdd:HHmmss}: {Level}: {Source}:
{Category}: {Message}: {Details}"
SmtpServerName="corp.dir.your-domain.com" SmtpPort="25" />
<add name="FileLogger" type="XQuiSoft.Logging.FileLogProvider, XQuiSoft.Logging"
FilePath="logs\application-{Timestamp:yyyyMMdd}-log.txt" ActiveRoot="false"
ExceptionProviderName="Failover"
ItemFormat="{Timestamp:yyyyMMdd:HHmmss}: {Level}:
{Source}: {Category}: {Message}: {Details}" FilterName="Verbose"/>
<add name="Failover" type="XQuiSoft.Logging.FileLogProvider, XQuiSoft.Logging"
FilePath="failover-{Timestamp:yyyyMM}-log.txt" ActiveRoot="false" />
</providers>
</Log>
<FilterManager>
<providers>
<add name="Verbose" type="XQuiSoft.Logging.LevelFilter,
XQuiSoft.Logging" MaxLevel="Verbose" />
<add name="ErrorsAndWarnings" type="XQuiSoft.Logging.LevelFilter,
XQuiSoft.Logging" MaxLevel="Warning" />
</providers>
</FilterManager>
</XQuiSoft.Logging>
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 believe 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?
NSpring code:
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 appender), or you have to get it based on reflection.
Log4net (option 1):
ILog Log = LogManager.GetLogger("BufferingForwardingAppender");
Log.Debug("Test log message");
Log4net (option 2):
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");
Enterprise library:
Logger.Write("Message To Log", "Category Name", 0);
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 its 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:
| Application Name |
Iterations |
Avg RPS |
Loss |
| baseline application |
331,709 |
1,104.24 |
0% |
| XQuiSoft file logger |
324,862 |
1,081.50 |
2.059% |
| XQuiSoft console logger |
309,499 |
1,030.51 |
6.677% |
| log4net console logger |
330,333 |
996.92 |
12.436% |
| nspring file logger |
258,899 |
861.49 |
21.983% |
| log4net file logger |
248,153 |
824.85 |
25.302% |
| nspring console logger |
199,719 |
664.74 |
38.801% |
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 timestamp down to the minute (i.e., 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 occurring.
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 erratic 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 on the enterprise library for a few reasons. First, I couldn't get them to run. Apparently, you can't just xcopy the ent lib DLLs and use them. You have to install the performance counters. An error on the web page is related to performance 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 comparisons 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
On of June 12th, 2006 a new version of the Logging component updated how exceptions are handled. The earlier version initially took a different approach to exception handling. First, I generally have two major rules in exception handling.
- 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.
- 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 logs 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 occurred 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. Configure a NullLogProvider 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 comparison and see what the results are?
If you already extensively use another logging component 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, available on Sourceforge. The sample code was not updated since no API changes were made.
- June 18, 2009: Links updated. Added configuration sample. Updated to component version 2.2.50727.0, available on sourceforge. The sample code was not updated since no API changes were made.
- December 6, 2010: Updated with a few new features and new log providers
