Thursday, June 28, 2007

Logging and Unit-Testing

Imagine the following situation:

1 public class SomeService {

2 private static ILogger _logger = new Logger<SomeService>();

3 //...

4 public void DoSomething() {

5 _logger.Debug("I log something cheap {0}", _service.DoSomething());

6 //...

7 if (_logger.IsDebugEnabled()) {

8 _logger.Debug("I log something expensive {0}", _service.DoSomethingElse());

9 }

10 }



How do we want to test that logging works in this situation?
A proposed solution was:

13 [Test]

14 public void should_log_something() {

15 using(disable_appenders_and_introduce_new_appender = new MagicStringAppender()) {

16 _service_under_test.DoSomething();

17 Assert(disable_appenders_and_introduce_new_appender.AllMessages.Contains("I log ...");

18 }

19 }



And here is what I don't like about it:
  1. Static creation of ILogger: by this we make ourselves dependent of the concrete implementation of Logger class. This will pull other dependencies (like log4net) in the environment, despite the fact that these are irrelevant for the test. The logger will be created when the class(type) is instantiated.
  2. The check-before logging for expensive log operations, is too low-level. A macro might help (TRY_LOG_DEBUG(...)), or maybe delaying the expensive operation into a lazy delegate: _logger.Debug(Func a_delayed_string_generator). The only objection might be that wrapping the costly operation in a delegate creates an extra object, making in the worst case scenario, the logging even more expensive. (From what I know, delegates & closures are pretty cheap).
  3. Maybe we don't know which operations are cheap and which are expensive, maybe in time a cheap log call will evolve to an expensive one. I would prefer a uniform lazy_delegate or macro solution.
  4. We are trying to unit-test a scope which is too big: if the service sends a message to the logger interface, if log4net (and its wrapper) receive the message, if according to the configuration, the log message is sent to the right appender, etc... Suppose that we change the config, and log4net, and the test fails. Then we have a lot of fun debugging. We will say: "why isn't working, I haven't changed anything in months". Because the scope is too big, we have no chance to do a binary chop.
  5. We have built another big machinery to manipulate log4net at the wrong end. This machinery must be maintained and support (for example when we want to switch to another log engine)
What I would do (probably better):
  1. Explicitly specify that we want to log in constructor. Either inject an ILogger or an ILoggerFactory.
  2. Test only that the service sends a message to the ILogger interface (a mock or a stub recorder)
  3. Try to use a delegate for delayed/expensive computations.
  4. Use a main logger for the critical exceptions (like OutOfMemory)
---
Update:
- the post it is not about what am I trying to log, it is about "how" I am trying to log. (suppose the expensive operation is dumping a complex object tree to a human-readable-not-xml representation)
- I am not a proponent for logging-testing, but some people would like to do that (logging gives a chill-fuzzy feeling: "I don't know what I have implemented, QA also doesn't have a clue, and now we are relying on log files, on a production-customer-machine. hmmm..."

1 comment:

Ralf said...

Wait a minute! Why on earth would you use the calls to the _service as an argument for your logger calls?
You don't want to DoSomethingElse when Debugging is not disabled?
That looks like a very flexible service to me ;-)
Anyway I agree with you: Every class that needs a logger should advertise that need. Preferably in its constructor.
Using a delegate to defer evaluation is a nice idea.
Instead of a macro you could use ConditionalAttribute from the System.Diagnostics namespace.