Robust logging in applications using functional parameters

Just as logging components in applications should have no side effects on the components themselves the act of logging should not throw exceptions and cause an application to crash or a process to fail. Many times I have seen some or all of the following used as log statements:

log.Debug(string.Format("Value x: '{0}' - Value y: '{1}'", obj.Property, SomeFunction());

My issue with this is two fold:

• There is performance issue, if debug is disabled whilst the logging framework will not output to the log but the string.Format statement will still be executed.
• If either the object parameter is null, retrieving the property value or calling the SomeFunction method were to throw an error and it was not caught correctly the current process would fail.

The first issue is dealt with in one of two ways. Log4net (other logging frameworks are available) provides a method for the common log levels to supply a format string and a list of parameters. It will not format the string if the log level the log statement is being applied to is disabled.

log.DebugFormat("Value x: '{0}' - Value y: '{1}'", "a", 1);

If a format method is not available in the version of the logging framework it should still probably provide a way of testing if a specific logging level is enabled or not, this can also be quite useful if you wanted to build up a string using an arbitrary number of parameters or apply some logic to the building of the message.

if (log.IsDebugEnabled)
{
    var message = "foo" + x == y ? "bar" : "wibble";

    log.Debug(message);
}

Whilst the format method handles the issue of unnecessarily formatting a string it still has to evaluate any parameters. With the if statement the whole block would be ignored if the specific logging level was disabled. However both methods would still need to have some additional logic to deal with null references or other exceptions being thrown.

To simplify the need of having to constantly check if log a specific value will tear down your application you can use selection of extension methods that take in functional parameters allowing you to delay the execution of retrieving the data and ensure that if they are called they are called safely. An example syntax might look something like:

log.DebugFormat("Value x: '{0}' - Value y: '{1}'", () => obj.Property, () => SomeFunction());

log.Debug(() => SomeComplexMethodToGetALogMessage());

In my implementation I would first check that the logging level is enabled and then proceed in one of two ways. If logging using a single delegate to generate a message I would execute the delegate safely, if successful log the output otherwise log that there was an error logging a message with the specific exception. If I was logging using a string format and passing in a list of delegates I would evaluate each of the parameters safely and if any of them were to fail I would substitute a place holder for the failed value(s) and log what I can of the expected message as well as logging any failure(s). An example implementation might look like:

public static void Debug(this ILog log, Func<string> message)
{
    if (log.IsDebugEnabled)
    {
        log.Debug(TryAndResolveArgument(message));
    }
}

public static void DebugFormat(this ILog log, string format, params Func<object>[] argFunctions)
{
    if (log.IsDebugEnabled)
    {
        log.Debug(string.Format(format, TryAndResolveArguments(argFunctions).ToArray()));
    }
}

private static IEnumerable<object> TryAndResolveArguments(IEnumerable<Func<object>> argFunctions)
{
    return argFunctions.Select(TryAndResolveArgument);
}

private static object TryAndResolveArgument(Func<object> argFunction)
{
    try
    {
        return argFunction.Invoke();
    }
    catch (Exception ex)
    {
        Trace.WriteLine("Failed to resolve logging parameter");
        Trace.WriteLine(ex);
    }

    return "{error logging value}";
}

Auto mocking with NSubstitute and Windsor

I have now fully embraced the world of auto mocking and can now see past the illusion of magic and see it for its wire-up cleanliness. I do not want to have to introduce an additional frameworks,  I am a lover of NSubstitute and generally use Windsor as my IoC of choice. The following explains how to create an auto mocking test framework using the two however I am sure you can adapt it to other frameworks.

Auto mocking base class

I have taken the approach of using a base class because it is a better fit for how I do my testing but this could easily be done in a self contained component that can be created in a test fixture. Whilst my real implementation does more than I have put here the main functionality is to create a WindsorContainer, register the LazyComponentAutoMocker which is covered later and the actual class under test. There is then an opportunity in the derived class to do some custom wire up by overriding the SetUp method. It then creates an instance of the class under test via Windsor. The derived classes have the ability of getting hold of registered components or registering their own by calling GetDependency or RegisterDependency respectively.

[TestFixture]
abstract class AutoMockedTestFixtureBaseClass<TClassUnderTest>
{
    private WindsorContainer mockContainer;

    [SetUp]
    public void virtual AutoMockedTestFixtureBaseClassSetup()
    {
        SetUpContainer();

        SetUp();

        ClassUnderTest = mockContainer.Resolve<TClassUnderTest>();
    }

    private void SetUpContainer()
    {
        mockContainer = new WindsorContainer();
        mockContainer.Register(Component.For<LazyComponentAutoMocker>());
        mockContainer.Register(Component.For<TClassUnderTest>());
    }

    protected virtual void SetUp() { }

    protected TClassUnderTest ClassUnderTest { get; private set; }

    protected TDependency GetDependency<TDependency>()
    {
        return mockContainer.Resolve<TDependency>();
    }

    protected TDependency RegisterDependency<TDependency>(TDependency dependency)
    {
        mockContainer.Register(Component.For<TDependency>().Instance(dependency));
        return dependency;
    }

    protected void RegisterDependency<TService, TDependency>() where TDependency : TService
    {
        mockContainer.Register(Component.For<TService>().ImplementedBy<TDependency>());
    }
}

Lazy component auto mocker

The lazy component auto mocker uses Windsors ILazyComponentLoader interface to create a dependency on demand via NSubstitute.

public class LazyComponentAutoMocker : ILazyComponentLoader
{
    public IRegistration Load(string key, Type service, IDictionary arguments)
    {
        return Component.For(service).Instance(Substitute.For(new[] { service }, null));
    }
}

Putting it together

The following is an example of how we might test a single class with a single dependency.

public interface ISomeDependency
{
    public int SomeValue { get; }
}

public class SomeClass
{
    public SomeClass(ISomeDependency someDependency)
    {
        DependentValue = someDependency.SomeValue;
    }

    public int DependentValue { get; private set; }
}

We have defined SomeClass with a dependency of ISomeDependency. The class uses a single property from the dependency to wire up its own internal property.

class When_creating_SomeClass_with_a_given_dependency_value : AutoMockedTestFixtureBaseClass<SomeClass>
{
    protected override void SetUp()
    {
        GetDependency().SomeValue.Returns(5);
    }

    [Test]
    public void Should_return_value_from_dependency()
    {
        ClassUnderTest.DependentValue.Should().Be(5);
    }
}

As you can see the test wire up is very simple, you have a simple setup of the dependency using NSubstitutes extensions and a simple assertion on the class under test. Here I am using FluentAssertions to assert the value.