A weird Rails logger Pokémon

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 (migrations.log).

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.

Not intuitive

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 logger method:

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...

Broken

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 DataMigrations::Logger itself...

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:

https://api.rubyonrails.org/classes/ActiveSupport/TaggedLogging.html

# 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 NoMethodError:

DataMigrations::Logger.tagged(log_id).info("Log message")

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 ActiveSupport::TaggedLogging, the .tagged method, is not technically working because it's not added to delegate to the private .logger method.

Adding :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