Click here to Skip to main content
15,867,453 members
Articles / Programming Languages / C#
Article

A Comprehensive Logging Package for .NET

Rate me:
Please Sign up or sign in to vote.
4.91/5 (115 votes)
25 Oct 200311 min read 640.3K   4.5K   326   234
A Comprehensive Logging Package for .NET

Sample Image - nspring.jpg


Introduction

I've recently begun seriously working with the .NET framework. I found a need for a .NET logging framework, something offering more robust features and better scalability than the classes in the System.Diagnostics namespace. Not finding anything fitting the bill either in the .NET class library or on the web, I cowboyed up and rolled my own. After a month of work in my spare time to write umpteen lines of code and another two weeks to document everything, I feel like I'm at a good breathing point. (For a help-oriented message board, the project's bug-tracking system, the latest version of the project's code and documentation, and contact information, please visit http://sourceforge.net/projects/nspring.)


Background

My background for the last seven or eight years has mostly been in Java development; however, when the release of the .NET framework somewhat coincided with the buyout of my shop by a Microsoft-centered company, I was determined to learn everything I could about the competition. I spent some time getting my MCSD .NET, and learned a lot along the way about how Microsoft likes to do things. Well, I've been pleasantly surprised so far! All in all, I find the .NET Framework to offer a pleasing blend of performance and features. However (and I suspect that this may be mostly due to the youth of the platform) it is still missing crucial features, logging support among them.

What's so important about logging?

First off, I'm not saying that System.Diagnostics classes Debug and Trace are bad. They're fine for quick troubleshooting, and the choice of the name "diagnostics" for their name reflects the intent of these classes. This isn't quite the same as full-featured logging support, however; true logging is not just diagnostic but historical in nature. I would never, for instance, dream of writing an important server-side application that depended solely on Debug and Trace for recording information about configuration, client connections, etc. The performance isn't there, and neither are the programmability features I've come to expect in a good logging package, having dealt with several in different languages over the years.

You may skip the next section and go right to the programming samples if you like, then download the .zip file. It contains extensive HTML documentation, including a programming sample illustrating the use of each logger, event formatter, and data formatter type in detail. The documentation has actually taken me longer to write than the code.


Logging package features

The new logging package offers the following features, among others:

High performance: Classes Debug and Trace are slow; unbuffered use of these classes can entail a significant performance degradation in application code. Loggers in this framework provide buffering ability (asynchronous output) as well as other caching features; this results in ~500 nanosecond per-message log times on a P4-M 2.0GHz laptop. Further performance optimizations are planned for later releases.

Stability: Every class in the logging package is thread-safe and performance-tuned for use in a multithreaded environment. Also, logging-failure support can be provided via classes implementing the ExceptionHandler interface; since the Logger base class itself implements this interface, all loggers can provide failover logging support for each other.

Ease of use: Loggers provided in this package are easy to understand and to use. Each one represents a different form of output; many different pre-written loggers are provided, covering everything from email logging to database logging to various forms of file-based logging, and most of them can be easily configured by calls to their constructor methods. Care has been taken to make each interface as intuitively easy-to-use as possible.

Ease of extension: Users can define their own loggers, filters, exception handlers, event formatters, data formatters, and log levels with ease, usually by just instantiating an object or implementing one or two methods. For instance, a custom Logger subclass can be created by implementing just a single method and still gain all the benefits of the Logger class, including buffering support.

Levels: Each log message (Event) is accompanied by a "priority" level. Each Logger has an associated level, and discards all events lower than this default level, providing simple yet fine-grained message-filtering ability.  Users can also define their own levels, as long as they contain unique information.

Flexible filtering: A hallmark of good logging support is the ability to selectively discard logged data based on more in-depth criteria than can be provided by the use of levels.  Not only are many prebuilt filters provided in the NSpring.Logging.Filters namespace, but it's easy to implement custom filters by subclassing the Filter class.

Flexible formatting: Useful types of log-record formatting are supplied via the classes in the NSpring.Logging.EventFormatters namespace. The XMLEventFormatter is highly configurable, and users can also supply their own formatting logic by subclassing the EventFormatter class. A simple formatting language also provides a great deal in formatting flexibility.

Data support: Each log event can carry an object data "payload". Support is built in for correct output of all arrays, lists and dictionary classes, together with the ability to supply format strings for each primitive type, as well as such structures as DateTime and TimeSpan. Users can extend the data formatting abilities of loggers by subclassing DataFormatter. Three types of data-formatting implementations are provided out-of-the-box.

Partitioned access: Debug and Trace provide only two points of global access to logging facilities in your applications. This can be bad for many reasons, not least of which is that the default ways of segregating content (the Indent() and Unindent() static methods) were provided without any thought of multithreaded use. In other words, two threads attempting simultaneous use of Debug and Trace can interfere with each other. Also, while you can create various listeners for these two classes, the classes must implement their own filtering logic (entailing a worst-case exponential performance slowdown with each listener added) because all output is funneled through either Debug or Trace. This leads to the next point.

Naming: Loggers can be registered with one or more names using a LoggerRegistry object. The Logger class itself provides global named access to loggers by use of an internal static default LoggerRegistry.

Composition: Loggers in this framework can be added to each other as children, receiving hand-me-down events. Different logging structures can be created for different needs, all organized under one easy-to-use name. Filters can also be composed of other filters using the CompositeFilter class.

Event categorization: Debug and Trace provide only four possible data fields for each logged event: a string message, a more-detailed string message, a string category, and an object data payload. There are no provisions made for different applications/modules logging using the same logging subsystem, etc. Each Event object logged by the NSpring logging framework contains fields for timestamp, text message, data object, event category, event code, event ID, event severity level, application name, and system name. Many different variations on the Logger class' Log method are provided to make these easy to use, and log filters (via the Filter class and its children) are provided that work with each of the fields. Certain loggers (such as FileLogger and MessageQueueLogger) have the ability to "scatter" output to many different files, queues, etc. based on the properties of the events logged through them. The ability to send output to different named loggers also provides a useful degree of categorization ability.

Support for existing code: The logging package may be used with existing code that depends on Debug and Trace by use of the DebugLogger and TraceLogger classes; by using logger composition, the same output can easily be redirected through other forms of output as well. (Also in the works: a series of event-source classes that can listen to a variety of data sources, including Debug and Trace, and pipe the resulting data through logging classes.)


Programming sample #1: Logging to files

(This and the following two examples were taken at random from the project documentation.)

Instances of FileLogger write their output to files. The file path may be relative or complete, and may be hard-coded or a formatting pattern.

The logger will create any directories necessary to write to any file. Where it doesn't involve a large memory commitment, FileLogger caches knowledge of known directories to improve performance. Buffering/asynchronous output is highly recommended with this logger, as each file is closed between logging operations. Performance in unbuffered mode is acceptable for most situations, but performance in buffered mode is very fast.

File output may be "scattered" to multiple files by the use of a formatting pattern in the file path. This may be used, for example, to implement "rolling" log files, where output is redirected on a periodic (say, hourly) basis. Performance in scattering mode is still excellent, as the logger holds multiple streams open in buffering mode (unless the path contains often-changing information such as the event ID or any time-based token value containing the millisecond. Use of such volatile paths still works just fine, but it results in the opening and closing of a stream for each event, resulting in slower performance).

Archiving is supported through the use of the IsArchivingEnabled, ArchiveDirectoryPath, and MaximumFileSize properties. If archiving is enabled, any file that reaches the maximum size is moved to the specified directory, named with an extra extension containing timestamp data (in order to differentiate multiple archives of the same file) and an optional extra file extension in order to facilitate easy reading of archives. Archive compression is not supported in this release.

The event formatter used by default is an instance of PatternEventFormatter, using a FlatDataFormatter for data formatting. In the sample below, a factory method is used to create the logger, but it could also be created using a constructor method.

C#
using System;
using NSpring.Logging;

public class FileLoggerExample {

    public static void Main(string[] args) {
        // The first parameter here is the file path; the second, the output
        // pattern
        Logger logger = Logger.CreateFileLogger("c:\\temp\\nspring.log", +
            "{ts}{z}  [{ln:1w}]  {msg}");
        logger.IsBufferingEnabled = true;
        logger.BufferSize = 1000;
        logger.Open();
        logger.Log(Level.Debug, "My hamster's name is Wilhelmina");
        logger.Log(Level.Verbose, "She has two tails");
        logger.Log(Level.Config, "She wears a green mohawk");
        logger.Log(Level.Info, "She's studying to be an accountant");
        logger.Log(Level.Warning, "Chrysanthemums are her favorite food");
        logger.Log(Level.Exception, "Underneath that tough biker exterior," +
            " she's just a sweet hamster");
        logger.Close();
    }

}

Output written to c:\temp\nspring.log:

2003-10-13 12:25:25.895-04:00  [D]  My hamster's name is Wilhelmina
2003-10-13 12:25:25.895-04:00  [V]  She has two tails
2003-10-13 12:25:25.895-04:00  [C]  She wears a green mohawk
2003-10-13 12:25:25.895-04:00  [I]  She's studying to be an accountant
2003-10-13 12:25:25.895-04:00  [W]  Chrysanthemums are her favorite food
2003-10-13 12:25:25.895-04:00  [E]  Underneath that tough biker exterior,
    she's just a sweet hamster

Programming sample #2: Using logger composition

This shows a simple example of the use of the CompositeLogger class. Note how the messages are grouped by child logger. The explanation for this is that when in buffering mode, a logger always passes events in batches to each of its children in the hopes that they will take advantage of bulk-writing enhancements. If the parent logger were unbuffered, the statements would be interleaved.

C#
using System;
using NSpring.Logging;

public class CompositeLoggerExample {

    public static void Main(string[] args) {
        // This very simple pattern will help differentiate output
        Logger cl1 = Logger.CreateConsoleLogger("Logger 1: {message}");
        // of the two child loggers

        Logger cl2 = Logger.CreateConsoleLogger("Logger 2: {message}");
        Logger logger = Logger.CreateCompositeLogger(cl1, cl2);
        logger.IsBufferingEnabled = true;
        // If the buffer reaches this size, the logger's thread will
        // automatically awaken
        logger.BufferSize = 10000;
        logger.AutoFlushInterval = 15000; // This value is in milliseconds

        logger.Open(); // This causes the opening of the children

        logger.Log("My hamster's name is Wilhelmina");
        logger.Log("She drives a tiny dump truck");
        logger.Log("She always wins at arm-wrestling");
        
        logger.Close(); // This causes the closing of the children
    }

}

Output:

Logger 1: My hamster's name is Wilhelmina
Logger 1: She drives a tiny dump truck
Logger 1: She always wins at arm-wrestling
Logger 2: My hamster's name is Wilhelmina
Logger 2: She drives a tiny dump truck
Logger 2: She always wins at arm-wrestling

Programming sample #3: An XMLDataFormatter example

Each XMLDataFormatter instance formats data objects as XML. If a collection is formatted, it is considered to be one of two types: a map (such as a dictionary class) or a list (such as an array or any IEnumerable).

Casing and separator options used in constructing XML names can be set using the NSpring.Logging.XML.XMLFormatOptions class. Formatting of strings, primitive types, and certain structures (such as DateTime, TimeSpan and Decimal) is controlled by setting format strings on properties of the superclass. See the documentation of the DataFormatter superclass for more details.

C#
using System;
using System.Collections;

using NSpring.Logging;
using NSpring.Logging.Loggers;
using NSpring.Logging.DataFormatters;
using NSpring.Logging.EventFormatters;

public class XMLDataFormatterExample {    

    public static void Main(string[] args) {
        ConsoleLogger logger = new ConsoleLogger();
        EventFormatter eventFormatter =
            new PatternEventFormatter("{message}\n{data}\n");
        eventFormatter.DataFormatter = new XMLDataFormatter();
        eventFormatter.IsIndentationEnabled = true;
        logger.EventFormatter = eventFormatter;
        
        string s = "schmaltz";
        int i = 5;
        float f = 1.234567F;
        TimeSpan ts = new TimeSpan(1, 2, 3, 4, 555);
        DateTime dt = DateTime.Now;
        Hashtable h = new Hashtable();
        h["key1"] = "value1";
        h["key2"] = "value2";
        object[] oa = {s, i, f, ts, dt, h};

        logger.Log("A single string value:", (object)s);
        logger.Log("A single integer value:", i);
        logger.Log("A single float value:", f);
        logger.Log("A single TimeSpan value:", ts);
        logger.Log("A single DateTime value:", dt);
        logger.Log("A Hashtable value:", h);
        logger.Log("An array of the above:", oa);
    }

}

Output:

A single string value:
<data type="string">schmaltz</data>

A single integer value:
<data type="integer">5</data>

A single float value:
<data type="float">1.234567</data>

A single TimeSpan value:
<data type="duration">P1DT2H3M4.555S</data>

A single DateTime value:
<data type="dateTime">2003-10-09T18:47:05.181-04:00</data>

A Hashtable value:
<data type="map">
   <entry>
      <key type="string">key1</key>
      <value type="string">value1</value>
   </entry>
   <entry>
      <key type="string">key2</key>
      <value type="string">value2</value>
   </entry>
</data>

An array of the above:
<data type="list">
   <value type="string">schmaltz</value>
   <value type="integer">5</value>
   <value type="float">1.234567</value>
   <value type="duration">P1DT2H3M4.555S</value>
   <value type="dateTime">2003-10-09T18:47:05.181-04:00</value>
   <value type="map">
      <entry>
         <key type="string">key1</key>
         <value type="string">value1</value>
      </entry>
      <entry>
         <key type="string">key2</key>
         <value type="string">value2</value>
      </entry>
   </value>
</data>

Points of Interest

The main reasons for the speed of the logging framework are twofold: avoidance, wherever possible, of both object creation and synchronization. The bulk of the time quoted above (about 500 nanoseconds for logging a message in buffering mode on a laptop machine) is for constructing the single Event object, the only object creation necessary for logging a message. I haven't been able to come up with a workable object-caching scheme that will let me avoid creating this object, and still provide the openness necessary in an extensible API. However, I haven't yet explored .NET weak references, one area that shows definite promise.

Failing a further reduction (to less than one!) in per-message object creation overhead, I plan to at least defer the creation of this object. So, instead of an application thread driving the creation of an Event object and pushing it into the buffer, I may change things so that the application code pushes the event-related data into a series of arrays, leaving it to the logger's own thread to construct the Event object whenever it gets around to it. This should speed things up quite a bit.

One thing that helped a lot in reducing synchronization overhead was use of object copies and immutable objects; if something can't be changed by another thread, there's no need for synchronization. For instance, the internals of an EventFormatter subclass don't need to be synchronized, since things are arranged so that no two loggers ever use the same event-formatter object, instead storing inside themselves a copy of any passed-in object. I feel that avoiding even an uncontested lock acquisition can be crucial when you're worried about micro- and nanoseconds.

Pattern evaluation turns out to be quite speedy. In fact, testing the formatting of date pattern strings versus .NET date format strings shows that the .NET built-in formatting is slower. I guess it's true, sometimes, what they say-- the more generic the code, the slower the code. For a complete reference on the mini-formatting language, look in the appendix of the HTML docs.

I highly recommend NDoc, a utility put out by the NDoc project on sourceforge.net. I would've never turned out such professional-looking API docs without it.

In the works...

A configuration framework, centralized logging application, and several other enhancements.  I'd welcome help on this and other planned features, if you have the time.

History

  • Submitted on 2003-10-14

License

This article has no explicit license attached to it but may contain usage terms in the article text or the download files themselves. If in doubt please contact the author via the discussion board below.

A list of licenses authors might use can be found here


Written By
Technical Lead
United States United States
This member has not yet provided a Biography. Assume it's interesting and varied, and probably something to do with programming.

Comments and Discussions

 
GeneralRe: Excellent work Pin
Jeff Varszegi8-Nov-03 8:22
professionalJeff Varszegi8-Nov-03 8:22 
GeneralRe: Excellent work Pin
zhoulhh10-Nov-03 5:37
zhoulhh10-Nov-03 5:37 
GeneralThanks Jeff (Does Log4j really matter? ) Pin
Lubian Z30-Oct-03 13:17
Lubian Z30-Oct-03 13:17 
GeneralRe: Thanks Jeff (Does Log4j really matter? ) Pin
Jeff Varszegi30-Oct-03 16:31
professionalJeff Varszegi30-Oct-03 16:31 
GeneralEmail Logger Question Pin
quarks28-Oct-03 12:29
quarks28-Oct-03 12:29 
GeneralConfiguration Pin
Heath Stewart26-Oct-03 3:20
protectorHeath Stewart26-Oct-03 3:20 
QuestionA logging console? Pin
Member 49815725-Oct-03 10:51
Member 49815725-Oct-03 10:51 
AnswerRe: A logging console? Pin
Jeff Varszegi25-Oct-03 11:51
professionalJeff Varszegi25-Oct-03 11:51 
Hey, thanks a lot! Some new people just joined the project, and we're still in the midst of setting things up. The most-requested features so far, in no particular order:

1. Centralized logging application - Should at least be able to read from messaging queues and sockets (this means a socket logger should also be written, but that's a piece o' cake) I'm talking with a couple of people already about ideas for this, but nothing's set in stone. I'm sure we will knock it out in the next month or so. I imagine the default data store will be a database, but I want to support more than one back end-- might use J. Halleux' data access layer to do this in a clean way, I dunno. I imagine it will also be able to just log using any of the other loggers, and we may include a decent simple file-based storage system. This will probably feed into development of the console app you're asking about.

2. Configuration - I am writing the first go of this myself, and it's almost ready. I still want to run it by my project team for input, which I will do really soon. It should be ready for prime-time in about a week, I would think. I'm trying to get it done as fast as possible, but also in a nice, extensible way. One feature that it will support is automatic reloading/reconfiguration on a set schedule, so you can alter loggers (even switching them for other types) without restarting an application.

One other thing that I want to put into the configuration, but don't know if it will make it into this release, is the ability to redirect certain configuration sections to other sources: other files, URLs, etc.

3. Additional loggers, to write to UNIX syslog (Giles Forster is currently looking into this one), MS exception handling framework, and other targets.

4. Some facility for auto-including call stack information for tracing purposes. I'm not against this, but it has to be accomplished in a clean, resource-friendly way or I will kayo it.

5. Remote control - The ability to have the logging package, if its configuration indicates, listen on a socket or in some other way for remote commands to change logger configurations (levels, etc.)

6. Console - The thing you're asking about. It sure would be super-useful, but it's not been begun yet. Lots of people ask about it.

I've made additional performance enhancements to the way buffering is performed, too; I've converted to a segmented buffer, and I doubt I will get the buffering much speedier after this (except for one last synchronization-reduction trick I thought of, which may or may not actually work). These enhancements will find their way into a beta release very soon, together with the configuration addition and anything else the team gets done. I think that the centralized logging app will occur in this same beta release. The release should be very stable, but we won't be in any rush to turn it gold until it's been tested to hell and back. Now I have that luxury, since other people are chipping in. The next release will probably also contain new collections classes and other utilities.

Regarding #6, your request, one team member has some pretty cool ideas about auto-generating summary data, like a table of contents. Someone else mentioned sending admin alerts via a pager gateway or IM, which would be pretty useful. I had a thought this morning about making an HTML-file logger, that would automatically reformat an HTML file to contain log statements when new ones came through the pipe, then resave the file. It wouldn't do for large-volume situations, but I think it could be useful for someone, somewhere.

I view the console app as a must-have, together with the configuration stuff and centralized logging (I'll need that one for work sometime in the near future-- selfish me). Then I will concentrate on what I really want to work on, tuned data structures.

If you want, go out to the project page and sign up to be notified of new releases (http://sourceforge.net/projects/nspring). I will be sure to send out a very detailed letter when the beta release happens, okay?

Jeff


Thank you.

Jeff Varszegi
GeneralRe: A logging console? Pin
Member 49815725-Oct-03 12:00
Member 49815725-Oct-03 12:00 
GeneralVisual Studio .NET Solution Pin
KartaKhalsa24-Oct-03 7:46
KartaKhalsa24-Oct-03 7:46 
GeneralRe: Visual Studio .NET Solution Pin
Jeff Varszegi24-Oct-03 8:15
professionalJeff Varszegi24-Oct-03 8:15 
GeneralRe: Visual Studio .NET Solution Pin
KartaKhalsa24-Oct-03 8:44
KartaKhalsa24-Oct-03 8:44 
GeneralRe: Visual Studio .NET Solution Pin
Jeff Varszegi24-Oct-03 8:52
professionalJeff Varszegi24-Oct-03 8:52 
GeneralRe: Visual Studio .NET Solution Pin
Marc Clifton2-Dec-03 4:00
mvaMarc Clifton2-Dec-03 4:00 
GeneralIt is a nice-looking api Pin
Ben Phillips23-Oct-03 2:53
Ben Phillips23-Oct-03 2:53 
GeneralRe: It is a nice-looking api Pin
Jeff Varszegi23-Oct-03 14:18
professionalJeff Varszegi23-Oct-03 14:18 
GeneralRe: It is a nice-looking api Pin
Jeff Varszegi23-Oct-03 14:21
professionalJeff Varszegi23-Oct-03 14:21 
GeneralTuring Logging off for Release phase Pin
Member 35396022-Oct-03 11:28
Member 35396022-Oct-03 11:28 
GeneralRe: Turing Logging off for Release phase Pin
Jeff Varszegi23-Oct-03 2:16
professionalJeff Varszegi23-Oct-03 2:16 
GeneralRe: Turing Logging off for Release phase Pin
blingbling6923-Oct-03 14:24
sussblingbling6923-Oct-03 14:24 
GeneralRe: Turing Logging off for Release phase Pin
Jeff Varszegi24-Oct-03 9:15
professionalJeff Varszegi24-Oct-03 9:15 
GeneralRe: Turing Logging off for Release phase Pin
Member 3539606-Nov-03 14:49
Member 3539606-Nov-03 14:49 
GeneralOK, Convinced Pin
Pauljenkins22-Oct-03 11:03
Pauljenkins22-Oct-03 11:03 
GeneralRe: OK, Convinced Pin
Jeff Varszegi23-Oct-03 2:17
professionalJeff Varszegi23-Oct-03 2:17 
GeneralWell That Kills My Article... Pin
Stephen Quattlebaum22-Oct-03 7:14
Stephen Quattlebaum22-Oct-03 7:14 

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

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