Latest revision as of 22:20, 30 September 2010

The problem

For several years I have been using a very simple collection of logging classes inside many of my .Net applications. This collection is quite limited in that it only allows logging of plain text events to file. Also it is not thread safe or very easily extensible.

For a new project a more robust and extensible logging system is required. I also want to take the opportunity to explore the use of code contracts in both design and implementation, prompted in part by the inbuilt support for contracts in .Net 4.0.

I have a number of requirements. I want to be able to:

• Log any type of item.
• Log items to any type of destination, including but not limited to, the Windows event log, a file, the debug or console window inside the Visual Studio IDE or memory.
• Log items to a XML file in an efficient manner.
• Log to multiple destinations using a single logger.
• Specify how each item is formatted before output.
• Allow the severity for each log entry to be specified.
• Rollover a log file based on date or file size or any other specified criteria.
• Filter what items are logged and also be able to filter on properties of the item being logged as well as category and severity.
• Assign each item logged a category and allow filtering by category.
• Ensure all objects in the framework are thread safe.

I also want the framework to contain classes for the most common loggers, filters, formatters and rollover mechanisms including logging to a file, filtering by severity and category, and logging items in a XML format.

Initial Design

Below is my initial design. Central to this is the idea of a logger to which items can be logged to a specific destination, a filter that controls what items are logged and a formatter that determines how items are logged. A logger is not required to have either a filter or formatter but can have a maximum of one of each per item type logged.

The framework is required to be thread safe because it will be used in various real time multi-threaded applications where logger instances can be accessed from different threads.

Conventions

The naming of elements in this design will follow the standard Microsoft guidelines[1]. Class, method, property and enumeration names use Pascal case, all parameter names use camel case and interface names use Pascal case and start with a capital ‘I’. Properties in the design are shown with separate getters and setters, so that it can be easily seen which properties are read only, set only or have different access modifiers. However properties will be implemented using the inbuilt property mechanism where the getter and setters for a property have a single name. Constructor methods for classes have the same name as the class.

Logging Items

One of my core issues with the logging framework I currently use is the fact that only string values can be logged and only to a file. Another issue is the decreasing efficiency in which items can be logged to a XML file as the file grows in size. Hence the major requirements for this design are the ability to log any type of item, to any destination, and to a XML file in an efficient manner. Basically the framework needs to be able to serialise to plain text any type of data or object.

There were several approaches that could be taken to achieve this. The approaches I thought about were:

• Including a 'Log' method for each logger class for each type of item that was required to be logged. This was quickly discounted due to the maintenance issues that would be involved. Each time the framework was extended to allow a new item type to be logged, each logger class would need to be changed to include the new 'Log' method. This also violates the 'stable abstraction' principle as the logger abstraction would be constantly changing. This would also certainly be case of a ‘Fragile Base Class’ as each new item type added to the base logger class would break any derived classes.
• Having a single generic 'Log' method for each logger class that took as an argument an object of any type. This would allow any item type to be logged and the logger interface would certainly be stable. However, this would introduce complexity around assigning and using the appropriate filter or formatter for each item type. It would also require, at some point, casting of objects to their exact type, most likely using some sort of switch statement. This approach was discounted due to the gut feeling that while there were some nice advantages to this, it felt like a clumsy and inelegant solution and was likely to contain a switch statement smell.
• Having a logger class for each item type to be logged. This would be extensible but would require one class per item type per destination. It would also mean that the abstraction for the logger classes could not include any 'logging' methods as the interface would depend on the item type being logged. This approach did have some advantages in that it would be simple to type safe the formatters and filters, no casting of items being logged would be required.
• Taking the previous approach to the next level and instead of creating logger classes for each item type explicitly, define the logger classes as generic classes. This approach has all the advantages of the previous method but has the added advantage of being able to define a stable abstraction whose interface can include the 'logging' methods. This was the approach that was decided upon for implementation.

Generics was used because it nicely solved issue of being able to define a stable abstraction for a logger and it's logging methods. It also meant that loggers could be type safe and it eliminated any requirement to cast objects to another type or include switch statements to test for different item types being logged. It also allowed a compact, concise design that was readily extensible to allow any type of data to be logged. However, the use of generics did result in several issues which are explained in detail later.

Big Design Up Front

Below is the full design for the logging framework. Items of type T are logged to the desired logger. Logged items are formatted into a string using the formatter for the logger, checked if they pass the logger filter and if so are logged to the appropriate destination.

Loggers

There are six types of loggers included in the framework: CompositeLogger, ConsoleLogger, EventLogLogger, MemoryLogger, FileLogger and XMLFileLogger. In addition there is the base ILogger interface, and an abstract Logger class that the previous six loggers are derived from.

ILogger

This is the base interface for a logger that specifies that items of type T can be logged. In the first draft of this design the ILogger interface did not exist but was added when it came apparent that it would be useful to allow custom loggers to be created that allowed logging of multiple item types.

Logger

This is the abstract class that the six loggers included in the framework are derived from. This class uses the Template Method pattern in that the Logger class has an protected abstract Log method that takes an instance of a LogEntry object as it's parameter that must be implemented in any subclasses. This class implements all the Log methods defined in the ILogger interface. Each Log method implemented follows the same pattern. A LogEntry object is created and then the abstract Log method is called passing the LogEntry instance in.

CompositeLogger

This logger contains a collection of other loggers and allows multiple logs to be logged to with a single call. For the CompositeLogger, the filter is applied before the filters for the contained loggers but the formatter is not used. This breaks the implied contract for the formatter but could be solved by creating a new logger interface, a 'formatted logger' interface, which derives from the ILogger interface and move the reference to ILogEntryFormatter from ILogger into this new interface. This would also require a new abstract Logger class for the new interface to be created and the functionality regarding formatting from the Logger class to be moved into the new class. Then the CompositeLogger could remain derived from the Logger class but the other Loggers would now derive from the new FormattedLogger class. This would also be in line with the interface segregation principle.

This logger is designed to allow a single point to log any and all items. It was designed to allow such situations as an error logger that logged all errors to a file but only ‘fatal’ errors to the windows event log. It also kind of acts in the same manner as the decorator pattern where functionality can be added to an object. Using the CompositeLogger a single CompositeLogger can have the functionality required added by simply adding the required logger classes. It means that new functionality can be created as new logger types without having to modify the logger abstractions and interface.

ConsoleLogger

This logger logs items to the standard-out stream, which could be a DOS console window or the output window inside Visual Studio. I expect that this logger will primarily be used in debugging and related activities.

EventLogLogger

This logger logs items to the Windows application event log using the specified application name as the event log source. If the Windows event log source does not exist then it will be automatically created as and when required.

FileLogger

This logger logs items to the specified file. I anticipate that this will be the main logger used. Basically it allows items to be serialised and saved to a physical storage device. It allows for an optional rollover strategy to be specified, that allows the log file name to be dynamic. There are two rollover strategies available in the framework: date and file size. The date rollover strategy appends the current date to the end of the log file name. The file size strategy updates the counter appended to the end of the log file name whenever the size of the log file exceeds the maximum size specified. There is a more specialised version of the file logger for logging items to a XML file.

XMLFileLogger

This is a specialised version of a file logger and is designed to allow logging of items to a XML file in an efficient manner. This is achieved by splitting the log into two files: a header file and a data file. The header file is a standard XML document which contains an entity that points to the data file. This allows items to be logged to the data file by simply appending them to the end of the file.

MemoryLogger

This logger stores the logged items in an internal collection which will be exposed via a limited subset of normal collection operations. These include adding an item, removing an item, accessing an item by numeric index and removing all items as well as returning a read-only snapshot of the collection. In addition the enumerator is also based on the current snapshot of the collection so it is thread safe and not affected by changes made to the collection after the enumerator is created. Its intended use is to allow items to be stored for later display to the user, e.g. error messages. Hence the memory logger is the only logger that is observable. It raises events whenever items are added or removed from the internal collection. I originally thought to either create an observable logger or add the observable functionality into the abstract logger class. However, after reviewing the requirements for the framework it was decided that the memory logger was the only logger that would need to send notifications, a clear case of YAGNI.

Missing Loggers

There are several loggers that are not currently included in the framework as they are not presently required but could be in the future. These include a 'persistent' logger, an email logger, an SMS logger and a network logger. The 'persistent' logger would retry to log a log entry upon a failure during the logging process. There are obvious uses for this type of logger when logging to file, probably more so than for other types of loggers. This would likely to be some sort of wrapper class. The email and SMS loggers would send emails and SMS messages respectively. The network logger would send items via the network, using TCP/IP or another protocol and allow for some sort of acknowledgment to be received back from the remote destination. Also there is no support for the logging of multiple items in a single log call, e.g. no logger supports multiple parameters of type T in the Log methods. I did not expect to require this functionality though it would not be very difficult to extend the framework to allow this. Though there is some question about whether multiple items should be logged separately or as a single item.

Design and Code Contract Details

Below is a more detailed look at the design for the various elements of the design. Also included are the code contracts for each property, method and constructor.

Log Entries

A log entry describes a single item being logged and is an immutable class (see figure below). It was created to allow easy passing of an item to be logged to filters and formatters and to allow different types of log entries to be created at a later date. All properties for a log entry are exposed via public getters which allow the log entry formatters to format log entries into whatever structure is required. This also allows filters to filter on any of the LogEntry properties and any of the properties for the entry object being logged. This does violate the 'Tell, don't ask' principle and appears to violate the 'Keep data and behaviour together' principle. If the LogEntry class was modified to include a filter and formatting strategy this would avoid violating the above two principles but could be violating the ‘single responsibility’ rule and the ‘separation of concerns’ principle. I would argue that it is not the responsibility of the log entry class to determine how it should be formatted but it could be argued that the log entry should be responsible for determining if it matches a specified criteria or not. This could be achieved by adding a method that took the name of the property to match and the value to match, and the matching operation (equal to , not equal to etc) and return a Boolean indicating if the log item satisfied the criteria or not. It was decided not to go down this path simply for ease of implementation and for type safety in filter classes.

The current design as shown below has the major weakness of exposing the entry property which if it is not an immutable object would allow filters and formatter classes to possibly modify the properties on the entry object. One solution is to modify the LogEntry object to store the Entry as a string or as XML, and not as the type T. An advantage of converting the entry to XML is that C# has the ability to serialise most objects to XML natively and access to the properties of the entry would still possible but would make the entry stored in a LogEntry object immutable. The disadvantage is that there can be performance penalties.

Log Entry Filters

Log entry filters (see figure below) take a log entry instance and return a Boolean indicating if the log entry passes the filter criteria or not and are defined by the interface ILogEntryFilter. The framework will include two filters: category and severity.

The CategoryFilter is an immutable class and will accept a log entry if the category for the log entry equals the filter category based on regional settings. The SeverityFilter is an immutable class and will accept any log entry that has a severity equal to or greater than the filter severity threshold.

Log Entry Formatters

Log entry formatters (see figure below) take the supplied log entry instance, format it and return the result as a string. The framework will include three formatters: standard, message only and XML.

The StandardLogEntryFormatter formats each entry with the log date, category, severity and the entry text. The format for the log date can be specified in the constructor for StandardLogEntryFormatter. If it is not specified then the long date/time format from the local computer’s regional settings will be used. The MessageOnlyLogEntryFormatter returns just the entry text for the log entry. The XMLLogEntryFormatter returns the log entry in a 'shallow' XML format, with the log entry simply converted to a string. It would be quite a simple process to create a subclass of the XMLLogEntryFormatter that would serialise the entry object to XML automatically. The XMLLogEntryFormatter uses the template method pattern when formatting a log entry; it has been designed such that to create a XML formatter class for different log entry types will only require the overriding of the protected method CreateEntryElement to format the entry in the desired XML format.

Loggers

File Rollover Strategy

Design Patterns

There were three patterns consciously used in this design: strategy, observer and composite. The design also contains one pattern that was not deliberately included but developed during the initial implementation, which was the template method pattern.

The strategy pattern was used in the FileLogger class to determine what strategy was used to rollover the log file name. The observer pattern is used for the MemoryLogger class to allow events to be raised when items are logged or removed. It is actually what Microsoft calls the 'Event Pattern' where events and delegates are used instead of register, unregister and notify. The MemoryLogger also differs from the standard observer pattern because contextual information about the event is passed as part of the notification, in this case details about the items affected by the operation. The composite pattern used in this design does not exactly match that specified by the GoF composite pattern because the 'component', which in this design is the interface ILogger, does not include any child management methods. However I believe that this is a valid and widely used variation.

The template method pattern appears in several locations including in the abstract Logger class where the four public Log methods call an abstract method that is implemented in its subclasses.

Originally I hoped to use the decorator pattern to allow additional functionality to be added to a logger as required, such as observer and persistence. This was not possible due to the widely differing interfaces for the different loggers. If the interfaces were all the same then this pattern would have worked extremely well. However, it should be relatively simple to include in the abstract Logger class this extra functionality or to create new subclasses that provide it. With the ability to combine multiple logger instances into a single logger instance using the CompositeLogger, the latter approach is probably the better choice.

Implementation

By definition software frameworks should be designed using the 'open/closed' principle and this design is no exception. Following the OCP is the reason why filtering for loggers is defined as a strategy and not simply setting category and severity threshold filter values directly in the logger class. Where possible classes have been implemented as immutable. Most of the properties for the classes in this design only have getters and can only be set via constructors. In addition, all properties are only accessed via the getters and setters and all data is set as private, which follows ‘Riel's Heuristic 5.3 - Avoid protected data’.

Inheritance

This design was developed with the theory that all classes in the design would need to be extended at some point. Hence the design attempts to use object encapsulation rather than class boundaries. Object encapsulation normally means that data is defined as protected so subclasses have access. In this design all data is defined as private but all access is via getters and setters and all data items have at least a getter. Most of the getters and setters are defined as protected to restrict access to the class and any subclasses It was then a natural progression to implement most methods in the design using the Composed method[2] or the Template method pattern, where operations inside a class were broken down into small methods that each have a single task and which could be overridden by a subclass. An example of this is the abstract Log(LogEntry logEntry) method defined in the abstract Logger class, which is then required to be implemented in all the subclasses.

It was noted that C#, which was the language that this design was implemented in, did not allow methods and properties to be overridden by default. In order for a method or property to be overridden it needed to be marked up with the 'virtual' keyword. Otherwise methods and properties could only be shadowed. This I find very interesting and is a clear indication about how the designers of the .Net framework thought object orientation programming should be used. The .Net framework is clearly in the 'favour composition over inheritance' camp.

MemoryLogger

The MemoryLogger class stores items logged in an internal collection. Each item logged is converted into a string using the Formatter associated with the MemoryLogger and stored in a LogEntry of type string. The MemoryLogger class implements the INotifyCollectionChanged interface which is the standard interface in .Net for notifying listeners of changes to a collection and is the interface expected when binding collections to UI components. It is used for the MemoryLogger to provide consistency with standard practices in .Net. Using this interface does break the 'separation of concerns' principle because the event raised whenever the collection changes returns an event argument that includes properties which state what action took place and what objects were affected and not all the properties are required for the different actions. It also means that the listeners for the event would require some sort of switch to test for the different actions that could occur. It would have been cleaner to create a separate event for each action. This would of also allowed for a much simpler and cleaner refactoring of the design if it was necessary to move some of the notification events higher up in the inheritance structure, such as moving the 'item added' event to the base Logger class.

Windows Event Log

The EventLogLogger was expected to create the Windows event log source if it did not already exist. The current implementation does in fact do this. However, during testing it was discovered that there were security issues with regards to Windows Vista and Windows 7. Namely, to create a source an application must be running with administrator privileges. In practice the source for the event log will need to be created as part of the installation of the application using this logging framework, as installation programs must be run with administrator privileges.

Decorator Classes

In my original design the RollingFileLogger class was a decorator class for the FileLogger class. Its role was to change the file name that items were logged to based on a specified strategy. This was initially achieved by only overriding the LogFileName property to return a modified file name. The standard logging functionality in the base class would work as per normal except they would now use the new log file name. In practice this meant that the RollingFileLogger class did not call any methods on the wrapped FileLogger instance but used the inherited logging methods from the base FileLogger class. This worked as expected until the XMLFileLogger class was created. This class overrode some of the base FileLogger class functionality but as soon as an XMLFileLogger was wrapped by a rolling file logger then this new functionality was never used. This was only discovered when it was determined that there were missing unit tests and these were subsequently added. This issue was due to my incomplete understanding of the decorator pattern. The RollingFileLogger class should have created pass-through methods for each of the public methods and then it would have very quickly become apparent that overriding the log file name property on the rolling file logger would not work as desired. Essentially the rolling file logger class as it was implemented was simply a subclass of the file logger and not a decorator. So the decision was made to move the rolling over strategy functionality into the FileLogger class itself and the RollingFileLogger class was removed from the design.

Above: Figure showing the original FileLogger design.

Above: Figure showing the modified FileLogger design.

Weaknesses

The major weakness in this design is that the entry object being logged is exposed in the LogEntry object passed to the filter and formatter for the logger. This means that the entry object could be modified during the logging process, which if the object was a 'live' object could lead to subtle and hard to track down bugs. It would be possible to change the design to overcome this weakness but it is really the responsibility of the caller into a logger to ensure that the object being logged is either immutable or a copy. A related weakness is that

Another weakness is that the XMLFileLogger does not enforce that items must be logged in a XML format. As formatters are defined by what type of item that is being formatted and not in the output format it would not be possible to enforce this in the current design. It would also violate the 'Liskov substitution' principle and ‘Design by Contract’, as the preconditions for the formatter on the XMLFileLogger would be more restrictive.

Also the 'Liskov substitution' principle and ‘Design by Contract’ are violated by the CompositeLogger class. This is because the formatter property is not used. The implementation of the CompositeLogger throws an exception if the setter for the formatter is called. This also violates ‘Riel's Heuristic 5.17 - Avoid no-op overrides’. In the design there is no mechanism for the formatter for the CompositeLogger to be applied to items being logged. Unlike for the Filter, for which it is a simple case to apply the filter for the CompositeLogger before applying the filter for the loggers contained within.

Missing from the framework is ability to enable or disable loggers. I have never required this functionality although I could see circumstances where this would be useful.

While Generics allowed a much cleaner design there are some notable drawbacks. The major drawback is that each logger can only log items of a single type and the type of item to be logged must be pre-known. However, it would be normal to want to log multiple item types to a single logger, which requires a custom logger class to be created that implements the ILogger interface for each type logged. I think that in practice custom loggers would contain an instance of the desired logger of type string. Items being logged would be converted to a string and then logged using the internal instance. This would allow multiple items to be logged to the same destination without conflict. This would be particularly important when trying to log multiple item types to the same resource, such as a file.

While it does seem overkill to have both an interface and an abstract class for loggers, the interface was created to help overcome the limitation mentioned above. The abstract class was created to keep core functionality together and let the various logger subclasses only implement what varied for each type of logger. How well this works in practice remains to be seen.

At the end of the day all the loggers convert the item being logged into a string representation which is what is actually logged. This implies then that the design could be separated into two tiers: low level loggers that only log strings and high level loggers that use generics and contain low level loggers to perform the actual logging.

Code Contracts

One of my key goals in this project was to gain a clearer understanding of how code contracts worked, how they could be useful and what the best method of implementing them was. This was due in no small part to the inclusion of code contracts as part of the recent .Net 4.0 release.

Code contracts in .Net most commonly express preconditions, postconditions and invariants as Requires, Ensures and Invariant, which can be checked both statically and at run-time. In the table below is the full list of contract methods that are available.

I found code contracts, for the most part, a great method to express what was required for each method or property and what could be expected back in return. The static checking of the contracts inside the Visual Studio IDE exposed several possible bugs in the logging framework source code by returning errors where preconditions or postconditions could not be proven to be true or where they were proven to be false. There did, however, appear to be some issues with the static checker, where it reported some conditions as not proven but further inspection of the code clearly showed that they were. In these cases it was usually required to add invariants to the class affected. A common example was when there was a postcondition defined for the getter for a property; an invariant for the same condition would need to be added. Also the static checker was unable to prove a condition when a string value was tested for equality or inequality against a literal string. For example:

Contract.Requires(x != ""); -- was always reported as being unproven by the static checker.

whereas

Contract.Requires(x.Length > 0); -- could be proven

It was also found that contract conditions should be made as small as possible, i.e. it was better to have separate conditions for each test rather than combine the tests into a single condition. This is because the static checker would not consider the conditions

Contract.Requires(x != null);

Contract.Requires(x.Length > 0);

as being the equivalent of

Contract.Requires(x != null && x.Length > 0);

and therefore the condition

Contract.Requires(x != null && x.Length > 0);

would not prove

Contract.Requires(x != null);

In addition the order that conditions appeared could also be important during runtime checking. The order does not appear to be important for the static checker. Contract violation exceptions are, by default, outside the normal exception process. However it is possible for a normal exception to occur during the evaluation of a contract condition. For example:

Contract.Requires(x.Length > 0);

Contract.Requires(x != null);

would throw a normal exception if x was null. Rearranging the order so the test for a null value was first would mean that if x was null then a contract violation exception would be thrown as would be expected.

I also encountered a few issues when creating unit tests to validate the correctness of the contracts. Code contract violations throw exceptions that are outside the normal exception boundary and so cannot be handled by the standard exception handling methods, i.e. try/catch/finally. It is possible to test code contracts but it requires modifying the test classes to add an event handler that throws a normal exception for the ContractFailed event and then test in a normal try/catch block for the name of the contract exception. You are forced to test for the contract exception by name because there is no access to the contract exception class. Another issue with the code contracts in .Net was the fact that to define contracts on interfaces or abstract classes you are required to create a new class that implements the interface or implements the abstract class and define the contracts in the new class. This breaks several OO rules and means the definition of an interface or abstract class is now held in multiple places. In addition, the documentation that is produced from Visual Studio does not always contain the contract definitions found in the code. It appears that if you override or inherit a method or property then only any differences in the contract between the method/property and the parent method/property appear. Which means two things: first, information about contracts for a method/property can appear in multiple places and second for interfaces and abstract classes the contract information does not appear in the documentation at all. Another issue with the implementation of code contracts in Visual Studio is the lack of support for contracts. The IntelliSense inside the IDE shows the name of methods/properties, the description, any exceptions that may be thrown, but there is nothing listing the contract. I could not find any method inside the IDE that displayed what contracts were defined for a method/property.

I am not sure that I have implemented the code contracts correctly. Thinking about it a bit more, my comment about having to add in invariants to prove some conditions, normally for properties, is not quite correct. I now think that there should not have been contracts expressly stated for the property getters and setters but rather just invariant conditions should have been defined.

Below is a table of all methods for contracts in .Net 4.0.

Finally

While this design has been implemented in C# it has not yet been used for any real world application, and therefore has not yet been proven to be an effective or good design.

Files

The source code for this design can be found at

Source Code

References

1. ^ Design Guidelines for Developing Class Libraries
2. ^ Smalltalk Best Practice Patterns by Kent Beck