I've recently added logging to LightService. The organizers pipe log messages to whatever you define as your logger.
I, [LS] - calling organizer TestDoubles::MakesTeaAndCappuccino I, [LS] - @keys in context: :tea, :milk, :coffee I, [LS] - executing TestDoubles::MakesTeaWithMilkAction I, [LS - expects: :tea, :milk I, [LS] - promises: :milk_tea I, [LS] - keys in context: :tea, :milk, :coffee, :milk_tea I, [LS] - executing TestDoubles::MakesLatteAction I, [LS] - expects: :coffee, :milk I, [LS] - promises: :latte I, [LS] - keys in context: :tea, :milk, :coffee, :milk_tea, :latte
This blog post tells you the story of how I added logging to this gem I maintain.
What do you think of this code?
class WithReducer
attr_reader :context
def with(data = {})
@context = LightService::Context.make(data)
self
end
def reduce(*actions)
raise "No action(s) were provided" if actions.empty?
actions.flatten!
actions.reduce(context) do |context, action|
action.execute(context)
end
end
end
It's not that hard to figure out what's going on in this object. It has 2 methods, #with and #reduce. The #with method is simple, it creates a Context object through the factory method and returns self for chaining. #reduce takes an arbitrary number of actions and reduces them by calling their #execute method.
Ok, let’s add logging around this:
class WithReducer
attr_reader :context
def with(data = {})
logger.info("[LS] - calling organizer <#{organizer.to_s}>")
@context = LightService::Context.make(data)
logger.info("[LS] - keys in context: #{extract_keys(decorated.context.keys)}")
self
end
def reduce(*actions)
raise "No action(s) were provided" if actions.empty?
actions.flatten!
actions.reduce(context) do |context, action|
result = action.execute(context)
logger.info("[LS] - executing <#{action.to_s}>")
if defined? action.expects and action.expects.any?
logger.info("[LS] - expects: #{extract_keys(action.expects)}")
end
if defined? action.promises and action.promises.any?
logger.info("[LS] - promises: #{extract_keys(action.promises)}")
end
logger.info("[LS] - keys in context: #{extract_keys(context.keys)}")
result
end
end
private
def extract_keys(keys)
keys.map {|key| ":#{key}" }.join(', ')
end
end
This is the exact same core logic as the one in the first example, except it got polluted with logging. This code works, but seeing what the two instance methods do is not obvious, far from simple. What's wrong here? First, two separate concerns (logging and the core functionality) got squashed into one. Second, when the logging logic changes the underlying core logic will be touched violating the Single Responsibility Principle.
Logging and the core functionality of this code should be separated out. The logging needs to wrap around (decorate) the core functionality. It should look something like this:
A decorator - the WithReducerLogDecorator in this case - publishes the exact same interface as the object it decorates, it has the with and reduce methods. I started with those when I went about refactoring this:
class WithReducerLogDecorator
def with(data = {})
end
def reduce(*actions)
end
end
Then I "wrapped" the original logic with this decorator. The log decorator delegates the calls to the wrapped object, which is WithReducer in this case:
class WithReducerLogDecorator
attr_reader :decorated
def initialize(decorated = WithReducer.new)
@decorated = decorated
end
def with(data = {})
decorated.with(data)
end
def reduce(*actions)
decorated.reduce(*actions)
end
end
At this point it does not matter which WithReducer class I'd use. Using the original one or the decorated should produce the exact same functionality.
I started adding logging around the decorated methods, refactoring the #with method was first:
class WithReducerLogDecorator
attr_reader :decorated, :organizer
def initialize(decorated = WithReducer.new, organizer)
@decorated, @organizer = decorated, organizer
end
def with(data = {})
logger.info("[LS] - calling organizer <#{organizer.to_s}>")
decorated.with(data)
logger.info("[LS] - keys in context: #{extract_keys(decorated.context.keys)}")
self
end
...
end
Adding logging around the #reduce method was a bit harder. It reduces the provided actions by calling their execute method. There is no easy way to hook into that process just yet. However, calling the provided block within the reduce block opens up the routine for extension (Open/closed principle). I changed the original reduce method like this:
class WithReducer
...
def reduce(*actions)
raise "No action(s) were provided" if actions.empty?
actions.flatten!
actions.reduce(context) do |context, action|
result = action.execute(context)
# ::: Invoke the provided block :::
yield(context, action) if block_given?
result
end
end
end
The logging logic can now wrap around the #reduce method like this:
class WithReducerLogDecorator
...
def reduce(*actions)
decorated.reduce(*actions) do |context, action|
# ::: All this code is executed within the decorated reduce block :::
logger.info("[LS] - executing <#{action.to_s}>")
if defined? action.expects and action.expects.any?
logger.info("[LS] - expects: #{extract_keys(action.expects)}")
end
if defined? action.promises and action.promises.any?
logger.info("[LS] - promises: #{extract_keys(action.promises)}")
end
logger.info("[LS] - keys in context: #{extract_keys(context.keys)}")
end
end
private
def extract_keys(keys)
keys.map {|key| ":#{key}" }.join(', ')
end
end
And with that I wrapped the original #with and #reduce methods with logging from outside with a decorator. I separated the two concerns: the core logic and the logging around it. I only need to touch the decorator object when the logging logic needs to be changed and I don't even need to look at the logging code when the core logic changes.
I learned about these concepts 9 years ago when I used Aspect Oriented Programming (AOP). I was fascinated by Around Advices, where logging was applied around a routine, beautifully separating the concerns.
