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

Friday, June 15, 2007

F# FizzBuzz

I'm trying to learn F# as the "pragmatic-learn-a-new-changing-the-way-you-think-programming-language-every-year" (sorry about that, it must be the german influence).

Here are my FizzBuzz exercises, based on F# Active Patterns:

First try:

let (| fizz|_ |) x = if x % 3 = 0 then Some("fizz") else None

let (| buzz|_ |) x = if x % 5 = 0 then Some("buzz") else None

let (| fizzbuzz|_ |) x = if x % 15 = 0 then Some("fizzbuzz") else None

let print_fizzbuzz (x:int) =

let display text = print_string text; print_newline() in

match x with

| fizzbuzz text -> display text

| fizz text -> display text

| buzz text -> display text

| _ -> x.ToString() |> display

let _ = for i = 1 to 20 do print_fizzbuzz i done



Second try: refactor the recognizers to a single parameterized recognizer:


let (| is_multiple|_ |) n text x = if x % n = 0 then Some(text) else None

let print_fizzbuzz (x:int) =

let display text = print_string text; print_newline() in

match x with

| is_multiple 15 "fizzbuzz" text -> display text

| is_multiple 5 "fizz" text -> display text

| is_multiple 3 "buzz" text -> display text

| _ -> x.ToString() |> display

let _ = for i = 1 to 20 do print_fizzbuzz i done


(* we do get a warning that the syntax for the parameterized recognizers is under review and it might change in the future release *)

Please post or backlink for improvements :D

Tuesday, June 05, 2007

APIs, handling dependencies, agile architecture

Somebody said recently that Resharper is "not so lovely" since it cannot handle thousand of files... My argument is that the need to work simultaneously (in a solution) is a smell, and the fact that Resharper crashes at type-parsing with a "System.OutOfMemoryException" exception should amplify the smell (increase our awareness).

I think we have only two cases: inside the membrane, or outside the membrane. The core of the cell represents a service implementation, the membrane represents service definition, outside the membrane are the service consumers/users. Actually outside the membrane, is inside another membrane: the whole architecture should be splitted in components.

If we are inside we are working on the implementation of a certain service(object, component). Inside a component we have limited visibility, up to a component interface (the membrane). Maybe some other interfaces, or stand-alone components (without external dependencies, for examples enumerating). All refactorings, type-parsing should occur without problem in this component.

If we are outside, we are service consumers. But we cannot talk to the "core" of the cell, we see only the membrane: the component interface. So we are not influenced by the changes in the implementation of the service (aka the "core").

What happens if you are a producer and you need to modify service definition. If we don't have a few consumers, we could load all the required components in a solution (producer + all consumers), and refactor the whole thing. If we have many consumers, we need to use public API techniques: we declare the whole interface as obsolete, we declare and implement the new one. After x weeks we delete the old interface (the consumers are responsible for refactoring their own code).

Isolating the change, is a fundamental principle in designing maintainable architectures. In a world without membranes, we are just hurting each other.