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.

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.

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.

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.

If NSpring isn't working well for you (for whatever reason), you might also take a look at other .NET logging frameworks. There are dozens of logging frameworks for .NET now and using one is definitely a useful thing and will make you a better programmer.

This is a great idea and nicely documented but, unfortunately, the first few tests that I implemented (using the examples in the help file) show that it seems to want to hang on exiting the program if you do not call Close() and (more crucially for me) doesn't seem to output anything at all to the console logger until you do call Close().

Opening the project in VS2008 fails because the files are not in the places where the solution thinks that they should be, so I haven't (yet) stepped through to analyse the problem. Also, I haven't spent a lot of time on this (maybe an hour reading the docs and ten minutes trying to get it to output something). Maybe I've missed a crucial step but debug logging is the last thing that should fail in an application, so I'm a little bit worried about using it as it stands.

Are there any plans to spend some time on getting this going again? I assume that it used to work fine!

I too would like to use this with my VS 2008 app but have found it does not work quite as advertised. It does not seem to write to the Windows Event log and I am having trouble getting it to write via the composite logger - intermittent results to Console log and file log.
Any body have a solution or an explanation?

I was trying to open the nspring file included in your zip file. I was able to read the "Contents" and "Index" from the left panel, but as I clicked on an item, the right panel is just empty (blank). Is there anything I need to do before opening the chm file?

By the way, I'm pretty amazed by your personal project! Really impressed! The only suggestion would be to implement the CompositeLogger as a Singleton and use the Observer pattern for the child logger like in the "A C# central logging mechanism using the Observer and Singleton patterns" article.

I've read nearly all of the threads looking for an answer to my question. I have been trying to figure out how to get the auto archiving feature to work. The max file size doesn't seem to effect the output.

Does buffering work with archiving? If so, how does the MaxBufferSize effect MaxFileSize?

Well I've got things working fine now and must eat humble pie although in my defense, there is an error in your examples. When using a file logger be sure to create from the FileLogger class and not the base logger, here in C++:

Does anyone know of a log viewer GUI available which could be used with NSpring log files? I did a search in Google for "log viewer" and found some available for log4net, but I would really prefer to use NSpring. I'm impressed with everything about NSpring: the emphasis on high performance, ease of use, great documentation, flexibility, etc. My boss wants us to log tremendous amounts of debug data and wants to be able to easily extract data when there's a problem, such as being able to query for all log records within a particular time range and/or matching certain "categories" and all exceptions, etc. Is there another solution someone using NSpring has found for this? Also, does anyone know if the performance of log4net is worse than for NSpring? If so, that would be a very strong argument for NSpring. In that case, we might have to write a log viewer ourselves for NSpring. But my boss will not want to do that if we can get an already existing log viewer for a logging package that has good-enough performance. Thanks for any help you can give!

The performance of log4Net was worse in my testing, but you should test for yourself... and then come back and post the results here! Try logging 1,000,000 small messages to a file, for instance.

I never got around to a log cruncher for text files, but the way I used the package in several real-world projects, it was unnecessary. For high-volume distributed applications, where you want to be able to search and filter based on many criteria, database storage is a no-brainer (and also gives you easy availability to extra fault tolerance, recovery, security, and archiving features). With this in mind I usually log to a database with fields keyed to machine ID, application, user, time, etc. and then can filter and sort all day long.

I intended to release a standard logging service, which could accept messages from several input sources such as message queues, direct submission, etc. and would have a standard database format, but never had the time. The service would have been able to use different storage media, etc. It would be a no-brainer to write a few pages to view the data in the database, as you can do for yourself. Sorry it wasn't wrapped up in a neat little package, though.

Jeff, thanks for responding so quickly to my question. I mentioned your suggestion of logging to a database (instead of to files) to my manager, but he rejected that. Our new processes will be running on a PC; the legacy code is running on a server. He doesn't want to tie up the network sending volumes of logging messages over to the server, where the database is, and doesn't want to put a database on each PC. He likes the speed of your tool and thinks we might just write scripts to extract information from the log files, such as all entries between 2 times with a certain category, etc.

You're welcome, and thanks for the kind words. IIRC the buffer size is set to either 100,000 or 1,000,000 messages by default, and the flushing interval is 30 seconds by default. Unless you believe you will use up too much memory inside of 30 seconds plus the time to write the messages, due to an extremely high volume, I don't see anything wrong with the defaults. That said, something like 1,000 seems large enough to still be conducive to great performance.

I like the effective idea of this logging program.
My issue is that I would like to disable logging during normal operation but just enable it with a command line argument for example.
At the end I would like one central position to switch logging on/off but keep all the .Log lines in my code.

Christof, I think the best idea for now is in the main portion of your program, to read the command-line argument and disable or enable logging based on that. You can create a null logger to receive the log messages in the situation where you don't want to log.