Fail-Safe Logging

It is very rare nowadays to find a system without some kind of logging. When using built-in Trace or third party libraries, developers assume:

1. Logging is side-effect free to anything other than logging system itself
2. Logging is fail-safe

The first assumption is true when using default file-based log writer, but may fail with other implementations (topic for another post). The second assumption is also true for most cases. Let's analyze a few scenarios in which the second assumption fails.

Consider the following pseudo code:

void MyMethod() {
    var cnt = _service.GetCount(); 
    var sum = _service.GetSum(); 
    _logger.Debug(
        "Factorial: {0}, Avg: {1}, SomethingElse: {2}", 
        _calculator.Factorial(cnt), 
        Sum/cnt); 
} 

As you can see there are few problems with using logger:

1. Counting factorial is a heavy operation and should be done only if debugging is enabled.
2. Avg calculation will fail if cnt is 0, even if debugging is not enabled.
3. Number of expected parameters in format string does not match number of parameters passed to Debug() method and may throw an exception, even if debugging is not enabled (Whether an exception is thrown depends on logger implementation.)

To solve problem #1, most of logging framework provide helper methods similar to this one:

_logger.IsDebugEnabled() 

You can use it to check logger configuration before calling Debug() method. And you have to do it before each call to Debug() -- not very elegant. To solve the second problem, you have to add validations. The third problem is unsolvable without creating a custom method for each variation of parameters -- unrealistic for most cases.

Catching exception during calls to Debug() will give a workaround for problems #2 and #3. It will make logging fail-safe, but it will not provide clear validation for problem #2 or compile-time check for problem #3.

The code would look something like this:

void MyMethod() { 
    var cnt = _service.GetCount(); 
    var sum = _service.GetSum(); 
    if (_logger.IsDebugEnabled()) 
        try { 
            _logger.Debug(
                "Factorial: {0}, Avg: {1}, SomethingElse: {2}", 
                _calculator.Factorial(cnt), 
                Sum/cnt); 
        } 
        catch { 
            //swallow or do something meaningful with 
        } 
} 

The code above has to be done everywhere logging is used -- too much clutter. Let's try to move all that repeating code to the logging façade:

class LoggerFacade { 
    void Debug(Func<string> func) { 
        if (_realLogger.IsDebugEnabled()) 
            try { 
                _realLogger.Debug(func()); 
            } catch { 
                //swallow or do something meaningful 
            } 
    } 
} 

Add helper formatter (optional):

public static class Extensions { 
    public static string FormatWith(this string format, param object[] args) { 
        return string.Format(format, args); 
    } 
} 

...and we can use it more elegantly:

void MyMethod() { 
    var cnt = _service.GetCount(); 
    var sum = _service.GetSum(); 
    _logger.Debug(        
        () =>  "Factorial: {0}, Avg: {1}, SomethingElse: {2}"               
               .FormatWith( 
               _calculator.Factorial(cnt), 
               Sum/cnt)); 
} 

Because we pass lambda to the logging façade, heavy calculation and possible division by zero will happen only when lambda is executed (and this, in turn, will happen only if debugging is enabled). We solved all three problems stated at the beginning of the post and made logging completely fail-safe with a minor change to calling code.