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}";
}