Tell, Don't Log
Logging is necessary for programs that run autonomously but I have often found that its implementation has had a bad effect on the maintainability of my code. Pulling the code that does logging out of the objects that generate log-worthy events helps a lot. In C#, events and delegates provide good support for such a separation.
Why do I find that logging made my code hard to maintain? Firstly, logging code ends up scattered throughout classes adding clutter. Secondly, logging reduces cohesion: objects must build log messages in addition to performing their functional behaviour. Finally, it is difficult to reuse classes in different situations if they log via static functions or logger objects, which is a common way of using log4j and related frameworks.
In my current project we are using C# events and delegates to separate logging from application functionality. Objects fire events to report that significant things have happened. Those events are routed (via delegates) to objects that know how to format the events into a log, or do something else with them.
For example, I might have an object that performs some complex and lengthy analysis upon an index of stocks. I want to log errors that happen during analysis, and also log progress so that I can see how the analysis is progressing when I run the tool at the command line.
public delegate void ProgressHandler( Stock stock, int current, int total );
public delegate void ErrorHandler( StockItem stock, Exception error );
public class StockAnalyser {
public event ProgressHandler Progress;
public event ErrorHandler Error;
public StockAnalyser( IDataAccess dataAccess, IClock clock ) ...
public void AnalyseStocks( string indexCode, IAnalysisStorage store ) {
StockIndex index = dataAccess.LoadIndex(indexCode);
int i;
foreach ( Stock stock in index ) {
try {
double analysis = Analyse(stock);
}
catch( AnalysisException error ) {
AnnounceError( stock, error );
}
store.Add( stock, analysis );
AnnounceProgress( stock, i, index.Size );
i = i+1;
}
store.Save();
}
protected virtual void AnnounceProgress( Stock stock, int current, int total ) {
if (Progress != null) Progress(stock, current, total);
}
protected virtual void AnnounceError( Stock stock, Exception error ) {
if (Error != null) Error(stock, error);
}
private double Analyse( Stock stock ) ...
...
}
In my command-line application, I can connect the events to logging methods like this:
public class App {
public static int Main( string[] args ) {
IDataAccess dataAccess = new DataEnvironment(... parsed from args ...);
IClock clock = new SystemClock();
string indexCode = ... parsed from args ...
StockAnalyser analyser = new StockAnalyser(dataAccess, clock);
// Hook the logging functions to the events
analyser.Progress += new ProgressHandler(LogProgress);
analyser.Error += new ErrorHandler(LogError);
try {
analyser.AnalyseStocks(indexCode);
return 0;
}
catch( Exception e ) {
Console.Error.WriteLine( "failed to start analysis: {0}", e );
return 1;
}
}
public void LogProgress( Stock stock, int index, int count ) {
Console.Out.WriteLine( "{1} / {2}: {0}", stock.Code, index, count );
}
public void LogError( Stock stock, Exception error ) {
Console.Error.WriteLine( "{0}: {1}", stock.Code, error );
}
}
Using events makes it easy to replace logging with something more appropriate when the object is run in a different situation. For example, in a GUI environment I can connect the progress event to a progress bar and the error event to a method that collects errors to be shown to the user after the analysis has finished.
Of course, logging frameworks like log4j or log4net provide a lot of useful functionality: formatting, log rolling, different logging back-ends, etc. etc. I don't want to throw the baby out with the bathwater when removing logging code from my domain objects. Luckily, there is no reason that events and a big logging framework cannot work together: application objects can send events to objects that log those events through the framework. That way I get the best of both worlds.