Many ways to implement similar logic

I blame this article for setting me off on this path. The article proposed some logger extensions, which resulted in some code a bit like this:

    // Use the delegate Func to enable late evaluation of the expression if it's needed by the logger
    public class LogWrapper
    {
        private ILog log;
        public LogWrapper(ILog log)
        {
            this.log = log;
        }

        public void Debug(Func<string> message)
        {
            if (log.IsDebugEnabled())
            {
                log.Debug(message.Invoke());
            }
        }

        public void Info(Func<string> message)
        {
            if (log.IsInfoEnabled())
            {
                log.Info(message.Invoke());
            }
        }
    }

There’s nothing majorly wrong with that, you might say. It uses a Func – a neat delegate pattern for lambda expressions that return a value (there’s Action for void ones) – to avoid an expression being evaluated unless the logger is going to pay attention to it when the log.Debug or log.Info message is invoked. Quite neat.

However, in the real world, there are four examples of this function, not two, and the are all:

   if (log.SOMECONDITION())
   {
       log.SOMELOG(...);
   }

Now having four functions with essential the same implementation struck me as a problem worth solving.

I’ll say it now. For this trivial example, the above code was more than sufficient. Every alternative I’ve come up with is larger and less readable for the above.

The aim with such code, though, should be to program by difference rather than crank out boilerplate code, so I wanted to see my options.

As before, I started with a unit test suite – another example of RhinoMocks in action:

  [TestFixture]
    public class LogWrapperTest
    {
        private MockRepository repository;
        private ILog log;
        private LogWrapper logWrapper;

        [SetUp]
        public void Setup()
        {
            repository = new MockRepository();
            log = repository.StrictMock<ILog>();
            logWrapper = new LogWrapper(log);
            typedLogWrapper = new TypedLogWrapper(log);
            tupleLogWrapper = new LogWrapperWithTuple(log);
        }

        [TearDown]
        public void TearDown()
        {
            repository.VerifyAll();

            repository = null;
            log = null;
            logWrapper = null;
        }

        [Test]
        public void WillPutDebugMessageInDebug()
        {
            ExpectDebugMessageWhenDebugEnabled();

            logWrapper.Debug(() => "hello");
        }

        [Test]
        public void WillPutNoDebugMessageWithNoDebug()
        {
            ExpectDebugDisabled();

            logWrapper.Debug(() => "hello");
        }

        [Test]
        public void WillPutInfoMessageInInfo()
        {
            ExpectInfoMessageWhenInfoEnabled();

            logWrapper.Info(() => "hello");
        }

        [Test]
        public void WillPutNoInfoMessageWithNoInfo()
        {
            ExpectInfoDisabled();

            logWrapper.Info(() => "hello");
        }

        private void ExpectDebugMessageWhenDebugEnabled()
        {
            using (repository.Record())
            {
                log.Expect(x => log.IsDebugEnabled()).Return(true);
                log.Expect(x => log.Debug("hello"));
            }
        }

        private void ExpectDebugDisabled()
        {
            using (repository.Record())
            {
                log.Expect(x => log.IsDebugEnabled()).Return(false);
            }
        }

        private void ExpectInfoMessageWhenInfoEnabled()
        {
            using (repository.Record())
            {
                log.Expect(x => log.IsInfoEnabled()).Return(true);
                log.Expect(x => log.Info("hello"));
            }
        }

        private void ExpectInfoDisabled()
        {
            using (repository.Record())
            {
                log.Expect(x => log.IsInfoEnabled()).Return(false);
            }
        }
    }

I’ve included the full unit tests partly to prove that everything I did ended up as working code (I added more tests for the examples) and also to illustrate a reasonably refactored test suite with 100% coverage of this, albeit simple, functionality.

What we’re trying to do is avoid multiple functions in the log wrapper with the same implementation, and make the calling code “select the log to use”, rather than call a different function for each log. This seems more like programming by difference and avoiding duplication.

Method 1 – A tuple

Store the invocation of the ILog commands in some object and pass that object into the log wrapper as a parameter. Calling code:

tupleLogWrapper.Log(LogWrapperWithTuple.Debug, () => "hello");
tupleLogWrapper.Log(LogWrapperWithTuple.Info, () => "hello");

The tuples become readonly constant properties of the log wrapper class. The tuple class itself is a wrapper for using the delegates that it stores as the ILog-specific calls to do either Debug or Info logging. You end up with two extra objects in memory that are the wrapper’s wrappers for the logging operations.

   /// <summary>
    /// Log wrapper
    /// </summary>
    public class LogWrapperWithTuple
    {
        protected ILog log;
        public LogWrapperWithTuple(ILog log)
        {
            this.log = log;
        }

        /// <summary>
        /// Log a message
        /// </summary>
        /// <param name="logger">to which log</param>
        /// <param name="message">function to evaluate if logging is active</param>
        public void Log(Logger logger, Func<string> message)
        {
            if (logger.IsActive(log))
            {
                logger.Log(log, message.Invoke());
            }
        }

        /// <summary>
        /// Logger operations
        /// </summary>
        public class Logger
        {
            private Action<ILog, string> logCommand;
            private Func<ILog, bool> isActive;

            public Logger(Action<ILog, string> logCommand, Func<ILog, bool> isActive)
            {
                this.logCommand = logCommand;
                this.isActive = isActive;
            }

            public bool IsActive(ILog logger)
            {
                return isActive.Invoke(logger);
            }

            public void Log(ILog logger, string message)
            {
                logCommand.Invoke(logger, message);
            }
        }

        /// <summary>
        /// List of logs we can use
        /// </summary>
        public static readonly Logger Debug = new Logger((log, message) => log.Debug(message), (log) => log.IsDebugEnabled());
        public static readonly Logger Info = new Logger((log, message) => log.Info(message), (log) => log.IsInfoEnabled());
    }

There are a lot of lines of code there, but nothing is especially complex, and I like the last two lines where the relationship between “Debug” and what that means for ILog is defined as kind of data.

Method 2 – Do it with class

I started with the calling code here. I wanted to have a class of logging call. So I wanted calling code that read like this:

typedLogWrapper.Log<Debug>(() => "hello");
typedLogWrapper.Log<Info>(() => "hello");

Isn’t that nice looking? It really expresses the intent. However, it requires a bit of heavy lifting to do it. C# generics are good, but they still require a common base class if you’re going to be calling functions. So there needed to be some objects, not just types, and this meant that every call to Log would cause an object to be created.

However, I made most of the actual linkage between the Type of logging call and ILog part of the static state of the classes, so the majority of the object that got created was static. Tiny objects are created and destroyed all the time, even when you call functions, so I didn’t think this was going to be a big overhead. The code is still a bit large.

    /// <summary>
    /// Base class for operations - stores logging commands in its static state
    /// </summary>
    /// <typeparam name="T"></typeparam>
    public class Operation<T>
    {
        protected static Func<ILog, bool> isEnabled;
        protected static Action<ILog, string> logCommand;

        public bool IsEnabled(ILog log)
        {
            return isEnabled.Invoke(log);
        }
        public void Log(ILog log, string message)
        {
            logCommand.Invoke(log, message);
        }
    }

    /// <summary>
    /// A debug logger
    /// </summary>
    public class Debug : Operation<Debug>
    {
        static Debug()
        {
            isEnabled = log => log.IsDebugEnabled();
            logCommand = (log, message) => log.Debug(message);
        }
    }

    /// <summary>
    /// An info logger
    /// </summary>
    public class Info : Operation<Info>
    {
        static Info()
        {
            isEnabled = log => log.IsInfoEnabled();
            logCommand = (log, message) => log.Info(message);
        }
    }

    /// <summary>
    /// Log wrapper which requires you to specify the type of logger to use
    /// </summary>
    public class TypedLogWrapper
    {
        private ILog log;
        public TypedLogWrapper(ILog log)
        {
            this.log = log;
        }

        public void Log<T>(Func<string> message) where T : Operation<T>, new()
        {
            T logOp = new T();
            if (logOp.IsEnabled(log))
            {
                logOp.Log(log, message.Invoke());
            }
        }
    }

It is also in neat self-contained segments, and the calling code looks good, so there’s always a trade-off.

Summary
Simplicity is best. The above patterns are not suitable for our trivial logging example, but as the heavy lifting increases and we want to specialise a method to multiple variants of code using a lot of compile-time set-up, then these patterns are potentially useful.

The trade-off is interesting. In the version with tuples, there’s virtual no additional object creation going on, but the calling code is a bit more verbose and less readable. In the version with types, the calling code is nice, but little objects get created so that the type-specific things can be achieved, so memory and performance could be a consideration if it was some weird realtime thing.

There is another alternative to the second option, which is to avoid the log wrapper altogether and ONLY have the type-specific loggers, passing the logger in.

Debug.Log(logger, ()=>"hello world!);

That seems even simpler and I’m sure you would work out its implementation. It didn’t occur to me as this version of the logger is not encapsulating away the original ILog, which is kind of the point of having a wrapper.

Overall, avoiding a parallel series of almost identical functions or calculations is always worth investigating to see if there’s a general pattern that can be extracted, but be critical of the resulting code. There’s always another way of doing it.

Advertisements

4 comments

  1. As you said, simplicity is the best, so the static extension methods from myPOV should be used for the “late execution” in the “logging example”…..

    There was a discussion in a german clean code community regarding roman numerals, if the following code is good or bad ->

    static uint[] nums = { 1000, 900, 500, 400, 100, 90, 50, 40, 10, 9, 5, 4, 1 };
    static string[] rum = { “M”, “CM”, “D”, “CD”, “C”, “XC”, “L”, “XL”, “X”, “IX”, “V”, “IV”, “I” };

    static string ToRoman(uint number) {
    string value = “”;
    for (int i = 0; i = nums[i]) {
    number -= nums[i];
    value += rum[i];
    }
    }
    return value;
    }

    The funny thing was that, they provided “clean code solutions” here C#

    http://codepaste.net/h9od88

    and here Java

    which are not “understandable” by just reading them 😦

  2. Here http://pastebin.com/Uebwc4fT I implemented your method 2 with an extension method…
    Also I (based on your idea) moved the logic from the wrapper to the “operation class”, which I renamed to “Switch” … hard to explain in englisch, I believe you see what I mean, when you see the code 😉

  3. Hey JJ – can you also paste up the “calling code” so we can see how this is used.

    Of all of these techniques, I still think the static extension methods is the simplest, closely followed by a plain-old wrapper. The wrapper class is the most honest.

  4. Hello Ashley,

    here the calling code …. it is the same like yours, the only difference, I have not to instantiate the Wrapper Class.

    Greetings JJR

    ILog log = new ILog();
    log.IsDebugEnabled = false;
    log.IsInfoEnabled = false;
    log.Log(()=>”Debug show not please!”);
    log.Log(() => “Info show not please!”);
    log.IsDebugEnabled = true;
    log.IsInfoEnabled = false;
    log.Log(() => “Debug”);
    log.Log(() => “Info show not please!”);
    log.IsDebugEnabled = false;
    log.IsInfoEnabled = true;
    log.Log(() => “Debug”);
    log.Log(() => “Info”);
    log.IsDebugEnabled = true;
    log.IsInfoEnabled = true;
    log.Log(() => “Debug”);
    log.Log(() => “Info”);

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 )

Google+ photo

You are commenting using your Google+ 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 )

Connecting to %s