Revision as of 23:51, 16 September 2010

Cosc427 Design Project 2010 - Darryl Anderson

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.

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 will use Pascal case; all parameter names will use camel case and interface names will use Pascal case and start with a capital ‘I’. Properties in the design will be 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.

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

Loggers

I envisioned five basic types of logger: composite, console, event log, file and memory.

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 would require changing the design in an unacceptable way. Either a setter would be required for the formatter property of a logger so the CompositeLogger could set the internal loggers to use the formatter for the CompositeLogger or pass the formatter to use when calling a logging method. This design has avoided the use of setters wherever possible. Using a setter for the formatter would introduce issues if an instance of a logger was added to multiple CompositeLoggers. Passing the formatter to use when calling a logging method is also unacceptable as it allows an external class to control the behaviour of the logger class and violates several principles including 'Tell don't ask'. 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. It was envisioned that this logger would 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. It is anticipated 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 what 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. It is not implemented exactly following the observer pattern as the events raised contain details about what item or items were affected by the operation. It was 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. The MemoryLogger class differs from the other logger classes in that the log entry formatter is used.

Common Functionality

During the in-depth design of the different logger classes it quickly became apparent that there was core functionality that was the same for all of the loggers. This lead to the creation of the abstract Logger class which contains all the common functionality. In particular the code for the public Log methods does not need to be duplicated for each type of logger because the public Log methods in the Logger class simply create a LogEntry instance and pass it to the abstract Log method which must be implemented in the different logger subclasses. This was implemented using the Template pattern.

One weakness with the design and using generics was that each individual logger class is only able to log one type of item. It was this that lead to the creation of the ILogger interface. This meant that custom logger classes could be created that did not derive from the abstract Logger class but more importantly it would be possible to create custom loggers that allowed multiple item types to be logged in the one class.

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

The Full Design

Below is the full design for the logging framework.

Log Entries

A log entry describes a single item being logged and is an immutable class. 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. This is partly overcome by the ReadOnlyLogEntry class where the Entry property is replaced by a string representation and hence is read only. It is envisioned that the Entry property for the ReadOnlyLogEntry will be the entry object serialised to a XML string. This will make the value read-only but still preserve the ability to access property values. This approach was considered for the LogEntry class and I believe that it is possible for any class to be automatically serialised to XML in C#, though there can be some performance issues. This approach may be looked at in the future if circumstances require it.

Log Entry Filters

Log entry filters 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 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

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

Where possible classes have been implemented as immutable and in accordance with the ‘open/closed’ principle. Most of the properties for the classes in this design only have getters and can only be set via constructors. In addition, all attributes 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 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.

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.

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.

As well as the CompositeLogger, the MemoryLogger also violates the 'Liskov substitution' principle and ‘Design by Contract’ because the formatter is used in a different manner than for the other logger classes. For the MemoryLogger the formatter is used to generate the string representation of the item being logged which is then stored in a ReadOnlyLogEntry object. For the other loggers (apart from the CompositeLogger) the formatter is responsible for formatting the entire log entry not just the item being logged. While the use of generics seemed to be an elegant solution to the requirements it does mean that each logger class can only log items of a single type. As it would be normal to want to log multiple item types to a single logger this would appear to be a major drawback to the design.

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.

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 single conditions. 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 != “”);

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.

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