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.

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.

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.

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 ↑