I love codebases for the surprises they offer. Some pieces of code jump at you like rare Pokémons and you gotta figure out what kind of a species it is and what it can do.
Gotta catch'em all!
In one project that I'm contributing to, I've recently encountered a Rails logger that I found weird. It's a special logger that is supposed to be used for data migrations and log to a specific log file (
class DataMigrations::Logger < ActiveSupport::Logger LOG_PATH = Rails.root.join("log/data_migrations.log") class << self delegate :debug, :info, :warn, :error, :fatal, :unknown, to: :logger private def logger @logger ||= ActiveSupport::TaggedLogging.new( ActiveSupport::Logger.new(LOG_PATH) ) end end end
The logger is designed to be used like this:
class DataMigrations::VideoThumbnailsToRecording def self.run DataMigrations::Logger.info("Start data migration") # ... more code ... end end
So far so good.
After working with this logger a couple of times, I encountered some problems with it. For one, it doesn't offer an intuitive way of usage. For two, it was hard to test. But most importantly, I find that it was broken.
I'm used to the Rails logger in Rails, it's easy:
Rails.logger.info("Log message") # Or... Rails.logger.tagged(log_id).warn("Almost failed 😬")
So maybe something like this would work too?
Migrations.logger.error("Better go home today, it doesn't make any sense at this point...")
Hard to test
As mentioned in my logger tests, I find value to test my loggers because I see them as part of the app's behavior and I want to see them working properly alongside the feature.
To recap real quick: In order to test your loggers, you need a logger instance so you can shove expected messages into it:
test "logger example" logger = Rails.logger expected_messages = ["message 1", "message 2"] logger.expects(:info).times(expected_messages.count).with do |actual| actual =~ expected_messages.shift end DataMigrations::VideoThumbnailsToRecording.run end
That's not possible here as easily because you can't get to the actual logger instance like this (it's
private). You need to hack your way in by accessing the private
test "logger example" logger = DataMigrations::Logger.send(:logger) expected_messages = ["message 1", "message 2"] logger.expects(:info).times(expected_messages.count).with do |actual| actual =~ expected_messages.shift end DataMigrations::VideoThumbnailsToRecording.run end
All of this might be easy to grasp now, but it might not be as obvious when you work with a logger like this for the first time, trying to understand what and how it is doing things...
I first wrote an ugly custom method inside of
DataMigrations::VideoThumbnailsToRecording so that my messages are prefixed with a
log_id to look like this:
"[ji32j32] Start logging" "[ji32j32] Log message 2"
One of the code reviewers mentioned that this is not the right responsibility for the data migration class and that it rather should go into
So getting back into the actual logger code, I noticed that our logger is a subclass of
ActiveSupport::TaggedLogging. Let's see what it can do:
# TL;DR logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT)) logger.tagged("BCX").info "Stuff" # Logs "[BCX] Stuff" logger.tagged("BCX", "Jason").info "Stuff" # Logs "[BCX] [Jason] Stuff" logger.tagged("BCX").tagged("Jason").info "Stuff" # Logs "[BCX] [Jason] Stuff"
Basically, the exact functionality is already there.
But doing this didn't really work, exploding with a
Because of the restrictive design of the logger:
# DataMigrations::Logger class << self delegate :debug, :info, :warn, :error, :fatal, :unknown, to: :logger
So the meat of the super
.tagged method, is not technically working because it's not added to delegate to the private
:tagged to the list of
delegate args solves the issue:
# DataMigrations::Logger class << self # Also adding :tagged to open up the interface a bit more: delegate :tagged, :debug, :info, :warn, :error, :fatal, :unknown, to: :logger