Make Rails test.log more useful

00_active_support.rb

# Based on https://ilikestuffblog.com/2008/06/18/find-tests-more-easily-in-your-testlog/
class ActiveSupport::TestCase

  setup :log_example
 
  private
 
  def log_example
    Rails.logger.info "\nStarting #{@method_name}\n#{'-' * (9 + @method_name.length)}\n"
  end
  
end

01_rspec_all.rb

RSpec.configure do |config|
  config.before(:each) do |example|
    message = format("[%s] %s %s", Time.current, example.metadata[:location], example.full_description)
    Rails.logger.warn  "#{'-' * message.length}\n#{message}"
  end
end

Rails.logger.level = ::Logger::WARN

02_rspec_logger.rb

class ExampleTestLogger < SimpleDelegator
  attr_accessor :description

  %i[<< add debug error fatal info log unknown warn].each do |meth|
    define_method meth do |*args|
      __getobj__.public_send(meth, description)
      __getobj__.public_send(meth, *args)
    end
  end

  def tagged(*tags)
    formatter.tagged(*tags) { yield self }
  end

  # def method_missing(meth, *args, &block)
  #   __getobj__.public_send(:warn, "LOGGER called: #{meth}(#{args})")
  #   __getobj__.send(meth, *args, &block)
  # end
end

Rails.logger = ExampleTestLogger.new(Rails.logger)

RSpec.configure do |config|
  config.before(:each) do |example|
    message = format("[%s] %s %s", Time.current, example.metadata[:location], example.full_description)
    Rails.logger.description = "#{'-' * message.length}\n#{message}"
  end
end

03_rspec_logger.rb

# Inspired by ActiveSupport::TaggedLogging.new
# see https://github.com/rails/rails/blob/89fab56597c335bb49887563b9a98386b5171574/activesupport/lib/active_support/tagged_logging.rb#L59
module ExampleTestLogging
  module Formatter
    attr_accessor :example

    def call(severity, timestamp, progname, msg)
      description = format("%s [%s] %s %s", timestamp, severity, example.metadata[:location], example.full_description)
      description_text = "#{'-' * description.length}\n#{description}\n"
      super(severity, timestamp, progname, "#{description_text}#{msg}")
    end
  end
end

Rails.logger.formatter.extend(ExampleTestLogging::Formatter)

RSpec.configure do |config|
  config.before(:each) do |example|
    Rails.logger.formatter.example = example
  end
end

04_rspec_logger.rb

# Final implementation
require 'io/console'

# Make test.log more useful!
RSpec.configure do |config|
  config.before(:suite) do
    defined? ::Rails and ::Rails.logger.unknown "STARTING SUITE #{ARGV}"
  end

  config.after(:suite) do
    defined? ::Rails and ::Rails.logger.unknown "FINISHING SUITE #{ARGV}\n#{'=' * IO.console.winsize[1]}"
  end

  config.around(:each) do |example|
    if defined? ::Rails
      ::Rails.logger.formatter.example = example
      example.run
      ::Rails.logger.formatter.example = nil
    end
  end
end

# Inspired by ActiveSupport::TaggedLogging.new
# see https://github.com/rails/rails/blob/89fab56597c335bb49887563b9a98386b5171574/activesupport/lib/active_support/tagged_logging.rb#L59
module ExampleTestLogging
  module Formatter
    DIVIDER_CHARACTER = '-'.freeze

    attr_accessor :example

    def call(severity, timestamp, progname, msg)
      description = format("%s [%s] %s", timestamp, severity, example_meta)
      description_text = "#{divider(IO.console.winsize[1])}\n#{description}\n"
      super(severity, timestamp, progname, "#{description_text}#{msg}")
    end

  private

    def example_meta
      if example.present?
        format("%s %s", example.metadata[:location], example.full_description)
      end
    end

    def divider(length)
      "#{DIVIDER_CHARACTER * length}"
    end
  end
end

::Rails.logger.formatter.extend(ExampleTestLogging::Formatter)