What I want from a logging framework

I keep being unsatisfied with our applications logging and I’ve decided to take a look at what I really want.

Obviously we want different levels of severity,

  • Exception
  • Error
  • Warning
  • Note
  • Debug

Those severities imply that we can filter by them and that we can possibly do different things based on encountering them. We also need to be able to specify different targets – file, debug view, event log and email.

There’s also another aspect that we don’t often think about but which I think is quite important, tying together the log messages into some sort of unit. This might be something like the import of an order on a system or perhaps a web page request.

There’s another thing related to that, timing. Not everything wants to be logged immediately. When we log straight to a file or a debug log we normally just keep writing the stream as we encounter it. If we want to log to an email we might want to batch together some of those message though. That also ties in quite neatly with the idea of units of work.

This would mean that if I have an error occur within a task I could see all the messages within that task, not just the errors. This would be an ‘intelligent’ mode of operation, rather than just one tied to a severity level.

This gives us a set of features something like this,

  1. Severity filtering
  2. Tying messages together into a unit of work or task
  3. Delayed sending
  4. Possibly optional logging based on severity, i.e. only display the notes if an error occurs.

Honestly we probably also want to have several separate configurations in action at once too so there’s the another feature to consider,

  1. A flexible configuration mechanism – this should be able to deal with multiple setups running at the same time

This makes me think a simple interface like this would be best,

public interface Logger
{
	void StartLevel(string name);
	void EndLevel(string name);
	void Error(string message);
	void Note(string message);
	void Warning(string message);
	void Debug(string message);
	void Exception(string message);
}

All that we would do is to create new classes that implement that to do the functionality we want. We presumably want them to be able to be composed of different ones and have different configurations but essentially when we log we log through an interface like that and it gets sent to a bunch of objects exposing that API.

In practice we would probably use it something like this,

Log.StartLevel("Interface run");
Log.Note("Interface running");
Log.StartLevel("Order Import");
Log.Note("Importing orders...");
Log.Note("Importing order XXXXX1");
Log.Note(" for destination WHS1");
Log.Error("Product D898223 does not exist, order XXXXX1 not imported");
Log.Note("Importing order XXXXX2");
Log.Note("Importing order XXXXX3");
Log.Note("Importing order XXXXX4");
Log.EndLevel("Order Import");
Log.EndLevel("Interface run"); // an email gets sent if an error occurred

One thing that irks is that if we have several paths storing the messages for some condition to become true, like sending an email when the interface has run or logging if an error occurs. We could even be storing all the debug messages when we are highly unlikely to send them. In practice though I think it’s worth keeping it simple, if there are really enough messages building up between flushes I suspect that we must have the applications architecture wrong. If not it can always be optimized then.

The configuration is the tricky bit.

<file-log>
<log-to-file>c:\logs\error_log.txt</log-to-file>
<severity-filter>Warning</severity-filter>
</file-log>
<!-- uncomment this to push debug output so that you can monitor it via DbgView 
<debug-log>
<debug-output />
</debug-log>
-->
<email>
<email-log>
<to>colin+newell@rugby-software.co.uk</to>
<smtp>smtp.someserver.com</smtp>
<from>interface@rugby-software.co.uk</from>
<subject>Interface problems</subject>
</email-log>
<trigger>Error</trigger>
<trigger-level>Interface run</trigger-level>
<severity-filter>Note</severity-filter>
</email>

I think that makes sense as a basic API and configuration mechanism. I think in practice it will need tidying and some more complexity adding but that should be the basics. All that I now need to do is the magic in between to make it work.

There’s also the problem of what to do in the case of exceptions to resolve. Ideally in those cases you would shortcut the trigger levels; especially since if we’ve just caught an exception it’s probably just busted through all those carefully constructed levels. Alternatively perhaps you simply add an alternative configuration block for them. Then it’s explicit and there’s no hard wired behaviour or complex contortions to try to express something complex in xml. Perhaps we’d just add a ‘flush log’ to implicitly dump all the previous log messages stored along with the actual exception report.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s