Explained: The Logger Virus

“Explained” is a series in which I endeavor to explain concepts that I’ve often found to trip up developers or teams. In the spirit of the “protégé effect“, I hope to strengthen my own understanding by helping others.

Understanding the infection

Logging is both a boon and bane to building and supporting production software. It’s critical to monitoring and diagnosing live systems. It’s also very challenging to know what and how much to log while the system is actively being built.

One of the more insidious impacts of logging is its tendency to infiltrate your design. As more and more components require monitoring, loggers extend their tendrils into more and more classes. Before you know it, the logger establishes itself as a prerequisite dependency for any piece of critical logic. It infiltrates your implementation like a virus.

Consider the example below — a pseudo code representation of a procedure that might be used to validate a signed HTTP request from a client.

public class SignatureAuthenticationProcedure : IAuthenticationProcedure
{
private readonly ILogger logger;
public SignatureAuthenticationProcedure(ILogger logger)
{
this.logger = logger;
}
public AuthenticationResult Authenticate(HttpRequest request)
{
this.logger.Trace("Beginning signature authentication procedure.");
AuthenticationResult result = AuthenticationResult.Failed;
try
{
this.logger.Trace("Validating timestamp.");
if(IsTimestampValid(request))
{
this.logger.Trace("Timestamp valid.");
this.logger.Trace("Validating signature.");
if(IsSignatureValid(request))
{
result = AuthenticationResult.Success;
this.logger.Information("Authentication successful.")
}
}
}
catch(Exception ex)
{
this.logger.Error(ex);
throw;
}
finally
{
this.logger.Trace("Completed signature authentication procedure.");
}
return result;
}
//
}

A handful of relevant lines of code are lost amongst an equal number of diagnostic statements. Our authentication procedure has become a logging procedure instead. The logging overwhelms the class. It is overburdened; it has too much responsibility.

This is exactly the type of problem that the Single Responsibility Principle is intended to solve. It states, in effect, that a component should be responsible for one thing. The intent is a reduction in complexity through an isolation of concerns.

Separating our concerns

In an ideal scenario, we can fulfill both our authentication requirements and our diagnostic requirements without one overcomplicating the other. A common means of detangling this type of relationship is through decoration. In such a scenario, a class wraps another to enhance it with additional behavior.

public class LoggingAuthenticationProcedure : IAuthenticationProcedure
{
private readonly ILogger logger;
private readonly IAuthenticationProcedure innerProcedure;
public LoggingAuthenticationProcedure(ILogger logger, IAuthenticationProcedure procedure)
{
this.logger = logger;
this.innerProcedure = procedure;
}
public AuthenticationResult Authenticate(HttpRequest request)
{
AuthenticationResult result;
try
{
this.logger.Trace("Beginning signature authentication procedure.")
result = this.innerProcedure.Authenticate(request);
if(result == AuthenticationResult.Successful)
{
this.logger.Information("Authentication successful.")
}
}
catch(Exception ex)
{
this.logger.Error(ex);
throw;
}
finally
{
this.logger.Trace("Completed signature authentication procedure.");
}
return result;
}
}

public class SignatureAuthenticationProcedure : IAuthenticationProcedure
{
public AuthenticationResult Authenticate(HttpRequest request)
{
AuthenticationResult result = AuthenticationResult.Failed;
if(IsTimestampValid(request) && IsSignatureValid(request))
{
result = AuthenticationResult.Success;
}
return result;
}
//
}

In the refactored example above we’ve separated the logging and authentication logic into two classes. Both implement the IAuthenticationProcedure interface. The SignatureAuthenticationProcedure is dramatically reduced in scope. It contains only the logic necessary to authenticate a request and is significantly easier to follow.

Similarly, our logging behavior is contained within its own class, LoggingAuthenticationProcedure. The class expects a reference to another implementation of IAuthenticationProcedure, a so-called “inner” procedure, allowing it to log its diagnostic messages around the invocation of the inner’s logic. In the example above, the class logs its beginning and end statements, its success message, and any unexpected errors that might occur.

Extra benefits

The LoggingAuthenticationProcedure is able to do all of this without influencing or imposing on the implementation of our business logic. That’s a win for maintainability but there are a couple of additional benefits as well.

  • Unit testing our business logic becomes quite a bit simpler. With logger references littered throughout our code, as we saw in the first example, we are left mocking loggers in all of our tests. This is messy and burdensome especially considering that we probably don’t particularly care about what is being logged. Our goal is to ensure that our business logic is behaving as expected. With the logger removed, our tests are more focused and maintainable.
  • We also gain a reusable component. As additional authentication procedures are added to the system, we need not implement additional logging. The LoggingAuthenticationProcedure is capable of wrapping any implementation of IAuthenticationProcedure and therefore can be reused as necessary.

Finishing the job

Prolific loggers will sometimes argue that this approach prohibits granularity in your diagnostic messages. You’ll notice in the last example that I dropped certain messages, such as those indicating the start and outcome of the timestamp validation step. I did this because my logging is now wrapped around the business logic rather than interleaved with it. I no longer have access to a logger to record such statements. On the face of it, it may appear that our prolific logger has a point.

But wait! Doesn’t the principle that we applied to get ourselves this far continue to hold? To the prolific logger I ask, “are you suggesting that our class holds responsibilities that warrant further monitoring?. How astute — it most certainly does still hold multiple responsibilities!”

Wait, what?

The implication that our class requires logging that is granular enough to differentiate between multiple tasks, which it will undertake, is a clear indication that it continues to bear too much responsibility. We’ve only taken our refactoring halfway. So, let’s finish it.

public interface IAuthenticationStep
{
bool IsAuthentic(HttpRequest request);
}

public class LoggingAuthenticationStep : IAuthenticationStep
{
private readonly ILogger logger;
private readonly IAuthenticationStep inner;
public LoggingAuthenticationStep(ILogger logger, IAuthenticationStep inner)
{
this.logger = logger;
this.inner = inner;
}
public bool IsAuthentic(HttpRequest request)
{
this.logger.Trace($"Beginning authentication step: {typeof(this.inner).FullName}");
var result = this.inner.IsAuthentic(request);
this.logger.Trace($"Step found request to be authentic: {result}");
return result;
}
}

public class SignatureAuthenticationProcedure : IAuthenticationProcedure
{
private readonly IEnumerable<IAuthenticationSteps> authenticationSteps;
public SignatureAuthenticationProcedure(IEnumerable<IAuthenticationStep> authenticationSteps)
{
this.authenticationSteps = authenticationSteps;
}
public AuthenticationResult Authenticate(HttpRequest request)
{
return this.authenticationSteps.All(step => step.IsAuthentic(request));
}
}

public class SignatureVerificationStep : IAuthenticationStep
{
public bool IsAuthentic(HttpRequest request)
{
//
}
}

public class TimestampAuthenticationStep : IAuthenticationStep
{
public bool IsAuthentic(HttpRequest request)
{
//
}
}

We can isolate the individual tasks that comprise our authentication procedure, which gives us the ability to decorate them with logging in the same manner that we did with the procedure itself. A common interface and individual classes for each step allows us to encapsulate each responsibility. An additional implementation, which focuses on logging these steps, allows our responsibilities to be decorated with logging capabilities. So, we achieve the granularity that our prolific logger desires, with a bonus of improved testability and code reuse to boot.

Photo: “Virus Graffiti, Trellik Tower” / CC BY-NC 2.0

Comments are closed.

Create a website or blog at WordPress.com

Up ↑