Click here to Skip to main content
Click here to Skip to main content

Overview of XQuiSoft Logging using the Provider Pattern (Open Source)

, 6 Dec 2010
Rate this:
Please Sign up or sign in to vote.
An Introduction to XQuiSoft Logging with a comparision to other log components

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 Smile | :) .

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

  1. DebugLogProvider - writes to System.Diagnostics.Trace and System.Web.TraceContext as applicable
  2. ConsoleLogProvider - writes to System.Console
  3. EmailLogProvider - writes log messages to email. Only recommended for error events requiring immediate attention.
  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. 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.
  6. 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.
  7. 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.
  8. 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.
  9. 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

  1. LevelFilter - Only accepts events within a given level range. MaxLevel and MinLevel define the range.
  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. The filter can be negated with the IsInclusive setting.
  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. 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");
    // 'Log.Info' is a constant integer value.

Enterprise library:

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

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

License

This article, along with any associated source code and files, is licensed under The BSD License

Share

About the Author

Mike Lang
Web Developer Nexul Software LLC
United States United States
Mike has worked in the .Net platform since the beta 2 release of version 1.0. Before that he worked on VB6 windows forms applications automating other applications such as AutoCAD and "Intent".
 
Mike has released a number of open source applications in javascript and C#.Net. Most of them can be found on github.
github/michael-lang
 
You can find older .Net open source projects on sourceforge at:
http://sourceforge.net/users/versat1474/
 
Mike is currently blogging at candordeveloper.com
Follow on   Twitter

Comments and Discussions

 
GeneralFailed to write log file under "Program Files (x86)" - Windows 7 PinmemberMichele Solazzi4-Apr-11 5:14 
GeneralRe: Failed to write log file under "Program Files (x86)" - Windows 7 PinmemberMike Lang4-Apr-11 6:59 
GeneralRe: Failed to write log file under "Program Files (x86)" - Windows 7 PinmemberMichele Solazzi5-Apr-11 5:47 
GeneralAbout Log4net... Pinmembervbfengshui6-Dec-10 6:54 
GeneralRe: About Log4net... PinmemberMike Lang6-Dec-10 7:28 
GeneralRe: About Log4net... Pinmembervbfengshui6-Dec-10 7:51 
GeneralNew release 2.5.3987 PinmemberMike Lang1-Dec-10 17:04 
QuestionCan multiple instances of the same application log to the same file safely? PinmemberMichele Solazzi12-Aug-10 3:02 
AnswerRe: Can multiple instances of the same application log to the same file safely? PinmemberMike Lang16-Aug-10 7:23 
Multiple applications cannot access the same file in write mode at the same time. The FileLogProvider does support multiple threads of the same application instance writing to the same file logger.
 
Options:
1) only allow one instance of your application to run at one time.
2) tell each application instance to log to different files. You can do this by setting the category of a log message to include the processID of the application, and then use the Category property to determine the log file name. Or you can do the same with the 'source' property. The issue here is that now you need to change everywhere you write a log message to put that value in the Log.Write call.
 
FilePath="~\log\{Source}-{Timestamp:yyyyMMdd-HH}-log.txt"
FilePath="~\log\{Category}-{Timestamp:yyyyMMdd-HH}-log.txt"

 

3) setup an exception log provider to the first file logger. That is you can define an alternate logger to attempt writing to if there is a failure to the first one. Then set a different file name convention for the secondary FileLogProvider. The problem is that the same app instance will not necessarily always go to the same file. You may get log events of both application instances intermixed.
 
4) when the second app instance opens you can have it run in a shadow folder, hence any relative paths in the FileLogProvider will go under that shadow folder. Take a look and see how NUnit works for help on that.
 
5) Use the DbLogProvider and write all events to a SQL Server (Express ok), or Oracle database instance instead.
 
6) Create a custom LogProvider that writes events to a web service, remotes messages to a single instance of a windows service, or other custom destination of your choosing. For instance, the custom wrapper could do option #2 for you. It could prepend the processId of the application to the Source of each event that it logs and then pass off the actual file writing to a FileLogProvider.
Michael Lang
(versat1474)
http://nexul.com/[^]

AnswerRe: Can multiple instances of the same application log to the same file safely? PinmemberMichele Solazzi20-Aug-10 2:06 
GeneralRe: Can multiple instances of the same application log to the same file safely? [modified] PinmemberMike Lang20-Aug-10 9:18 
GeneralRe: Can multiple instances of the same application log to the same file safely? PinmemberMike Lang1-Dec-10 16:54 
GeneralTab indentation, flush, max file size example, .NET3.5 & .NET 4.0 PinmemberMichele Solazzi4-Aug-10 0:54 
GeneralRe: Tab indentation, flush, max file size example, .NET3.5 & .NET 4.0 PinmemberMike Lang4-Aug-10 9:40 
GeneralRe: Tab indentation, flush, max file size example, .NET3.5 & .NET 4.0 PinmemberMichele Solazzi5-Aug-10 6:02 
GeneralRe: Tab indentation, flush, max file size example, .NET3.5 & .NET 4.0 PinmemberMike Lang5-Aug-10 6:44 
GeneralRe: Tab indentation, flush, max file size example, .NET3.5 & .NET 4.0 PinmemberMichele Solazzi5-Aug-10 8:42 
GeneralRe: Tab indentation, flush, max file size example, .NET3.5 & .NET 4.0 PinmemberMike Lang16-Aug-10 7:29 
GeneralRe: Tab indentation, flush, max file size example, .NET3.5 & .NET 4.0 PinmemberMike Lang1-Dec-10 16:56 
QuestionWhat about client / server architecture? PinmemberDaProgramma25-Jun-09 4:10 
AnswerRe: What about client / server architecture? PinmemberMike Lang25-Jun-09 4:37 
GeneralRe: What about client / server architecture? PinmemberDaProgramma25-Jun-09 5:34 
GeneralRe: What about client / server architecture? PinmemberMike Lang25-Jun-09 6:15 
GeneralNew release 2.2.50727.1 PinmemberMike Lang19-Jun-09 3:14 
GeneralNew release 2.1 PinmemberMike Lang8-May-09 4:00 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.

| Advertise | Privacy | Mobile
Web03 | 2.8.140814.1 | Last Updated 6 Dec 2010
Article Copyright 2006 by Mike Lang
Everything else Copyright © CodeProject, 1999-2014
Terms of Service
Layout: fixed | fluid