ActiveJobのloggerメソッドをスタブするはなし

こんにちは、Plex Job開発チームの種井です。

この記事は、 PLEX Advent Calendar 2024の23日目の記事です。

私の書いた前回、前々回の記事でSemantic Loggerを使用してRailsアプリケーションから出力されるログを構造化する取り組みについて紹介しました。今回はSemantic Loggerを使用して開発を行う中で、ログイベントのテストを作成する機会がありました。その上で、いくらか工夫したところがあったので紹介したいと思います。

また、Plex Jobでは

アプリケーションフレームワークとしてRails
テスティングフレームワークとしてはRSpec

を使用しているため、サンプルコードについてもRailsおよびRSpecの使用を前提として説明しています。

背景
ActiveJobのコードを見てみる
スタブする方法
どちらを使うか？
おわりに

背景

テストを作成していると、あるログイベントが発生したかどうかをテストしたいことがあります。そのような場合には、Rails.loggerの各メソッドの呼び出しを検証することになります。以下は、実装例となります。

class HomeController < ApplicationController
  def index
    # Does some stuff ...
    logger.info "Someone visited the site!"
    # Does some more stuff ...
  end
end

it "logs a message" do
  visit root_path

  expect(page).to have_content "Welcome to my site!"

  expect(Rails.logger).to receive(:info).with("Someone visited the site!")
end

everydayrails.com

Semantic Loggerでは、グローバルにRails.loggerを上書きする仕組み上、ログイベントを検証するにあたって、上記のような方法でログを検証することができません。 Semantic Loggerの公式ドキュメントにもあるように

context 'when it blows up' do
  let(:capture_logger) { SemanticLogger::Test::CaptureLogEvents.new } # ①

  it 'should should log the error' do
    allow_any_instance_of(MyThing).to receive(:logger).and_return(capture_logger) # ②
    MyThing.new('asdf').do_something!

    # ③
    expect(capture_logger.events.last.message).to include('Here is a message')
    expect(capture_logger.events.last.level).to eq(:error)
  end
end

①SemanticLogger::Test::CaptureLogEventsのインスタンスを作成する
② 対象のメソッドをallow_any_instance_ofを使ってスタブする
③ SemanticLogger::Test::CaptureLogEventsに対してログイベントを検証する

必要があります。

加えて今回はActiveJobを使った非同期処理に対してテストを書く必要があったので、loggerメソッドをスタブしてSemanticLogger::Test::CaptureLogEventsのインスタンスへと差し替える必要がありました。

以下は実装例です。

class SampleJob < ApplicationJob
  def perform(message)
    logger.info(message)
  end
end

require "rails_helper"  
  
RSpec.describe SampleJob, type: :job do
  describe "#perform_later" do
    let(:capture_logger) { SemanticLogger::Test::CaptureLogEvents.new }
      
    it "logs a message" do
        allow_any_instance_of(described_class).to receive(:logger).and_return(capture_logger)
          
        described_class.perform_now('message !!')
        expect(capture_logger.events.last.payload).to eq("message!!")
    end
  end
end

これでもログの出力をテストしたいという当初の目的は果たせますが、allow_any_instance_ofの使用はなるべく避けたいです。(RuboCopにも違反扱いされてしまいます) また、ActiveJobではloggerアクセサが定義されています。そのためRails.loggerではなくloggerメソッドを呼び出してログ出力を行うインターフェースであることも今回実装する上で考慮しなければならいないポイントでした。

今回は、allow_any_instance_ofを使用せずにActiveJobのloggerメソッドをスタブする方法を調査・実装したので紹介したいと思います。

ActiveJobのコードを見てみる

まずは、スタブする対象について調べてみることにします。 ApplicationJobはActiveJob::Baseクラスを継承しているため、そちらを見てみます。

module ActiveJob
    class Base
        include Core
        include QueueAdapter
        include QueueName
        include QueuePriority
        include Enqueuing
        include Execution
        include Callbacks
        include Exceptions
        include Instrumentation
        include Logging
        include ExecutionState
    
        ActiveSupport.run_load_hooks(:active_job, self)
    end
end

github.com

Loggingというモジュールをインクルードしています。

次にLoggingモジュールを見てみます。

module ActiveJob
    module Logging
      extend ActiveSupport::Concern

        included do
          ##
          # Accepts a logger conforming to the interface of Log4r or the default
          # Ruby +Logger+ class. You can retrieve this logger by calling +logger+ on
          # either an Active Job job class or an Active Job job instance.
          cattr_accessor :logger, default: ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT))

            ...
        end
        ...
    end
end

github.com

cattr_accessor でlogger属性が定義されています。cattr_accessorはクラス属性のクラス・アクセサとインスタンス・アクセサの両方を定義するアクセサです。また、cattr_accessorはmattr_accessorのエイリアスです。

公式ドキュメントの例を借りてmattr_accessorの挙動を簡単に確認してみます。

module HairColors
  mattr_accessor :hair_colors # ①
end

class Person
  include HairColors
end

# ②
HairColors.hair_colors = [:brown, :black, :blonde, :red]
HairColors.hair_colors # => [:brown, :black, :blonde, :red]
Person.new.hair_colors # => [:brown, :black, :blonde, :red]

① mattr_accessorによりhair_colorsクラス変数が定義され、同時にクラスアクセサとインスタンスアクセサの両方が定義される
② アクセサを使って値の参照や代入を行うことができる

ここまでで、AcriveJob::Baseクラスがどのようにloggerを定義しているかがわかりました。

テンプレートメソッドであるperform メソッドはインスタンスメソッドなので、インスタンスアクセサとして定義されたloggerをスタブするとよさそうだとわかりました。

スタブする方法

ActiveJob::Baseクラスがどのようにloggerを定義しているかがわかったところで、早速対象をスタブしていきます。 ActiveJob::Base.new メソッドの返り値をスタブすることで実現することができます。

class SampleJob < ApplicationJob
  def perform(message)
    logger.info(message)
  end
end

require "rails_helper"

RSpec.describe SampleJob, type: :job do
  describe "#perform_later" do
    let(:capture_logger) { SemanticLogger::Test::CaptureLogEvents.new }
      
    it "logs a message" do

        instance = described_class.new('message !!')
        allow(described_class).to receive(:new).and_return(instance)
        allow(instance).to receive(:logger).and_return(capture_logger)
          
        described_class.perform_now('message !!')

        expect(capture_logger.events.last.payload).to eq("message!!")
    end
  end
end

① あらかじめSampleJobのインスタンスをperform_nowと同じパラメータで作成しておく
② SampleJobクラスの初期化メソッドをスタブし、①のインスタンスを返すようにする
③ SampleJobのloggerインスタンスアクセサをスタブし、SemanticLogger::Test::CaptureLogEventsに差し替える

どちらを使うか？

ここまでで、allow_any_instance_ofを個別のインスタンスを指定する方法に書き換えることができました。それぞれの書き方を改めて並べてみます。

allow_any_instance_ofを使う方法

require "rails_helper"  
  
RSpec.describe SampleJob, type: :job do
  describe "#perform_later" do
    let(:capture_logger) { SemanticLogger::Test::CaptureLogEvents.new }
      
    it "logs a message" do
        allow_any_instance_of(described_class).to receive(:logger).and_return(capture_logger)
          
        described_class.perform_now('message !!')
        expect(capture_logger.events.last.payload).to eq("message!!")
    end
  end
end

allow_any_instance_ofを使わない方法

require "rails_helper"

RSpec.describe SampleJob, type: :job do
  describe "#perform_later" do
    let(:capture_logger) { SemanticLogger::Test::CaptureLogEvents.new }
      
    it "logs a message" do
        instance = described_class.new('message !!')
        allow(described_class).to receive(:new).and_return(instance)
        allow(instance).to receive(:logger).and_return(capture_logger)
          
        described_class.perform_now('message !!')

        expect(capture_logger.events.last.payload).to eq("message!!")
    end
  end
end

allow_any_instance_ofを使う方が、一見するとコードとしては短くなり、使わない方に関してはやや冗長な書きぶりになってしまいます。

今回は、後者のallow_any_instance_ofを使用しない方法を採用することにしました。

というのも、前半に少し触れましたがallow_any_instance_ofはrspec-mocks公式のドキュメントでも言及されているように推奨されていません。

rspec-mocksのAPIは個々のオブジェクトインスタンス向けに設計されているが、該当の機能はオブジェクトのクラス全体に対して作用するため意図しない挙動や可読性の低下を招いてしまう
この機能を必要とする時点で設計上の問題があることが多い。テストがあまりに多くのことをしようとしすぎているか、テスト対象のオブジェクトが複雑すぎる可能性が高い
rspec-mocksの最も複雑な機能で、歴史的に最も多くのバグ報告を受けている

上記のような理由から、Semantic Loggerの公式ドキュメントで紹介されているテストコード上でのログイベントの検証方法を採用せず、個別のインスタンスをスタブすることにしました。

おわりに

allow_any_instance_ofを個別のインスタンスに対してスタブするように書き換えるだけと言えばそうなのですが、ActiveJobのBaseクラスやCoreクラスの仕様をはじめフレームワークの構造をまず理解した上でスタブ対象の特定を行う必要がありました。同じようなケースでallow_any_instance_ofの書き換えを検討している方の参考になればと思います。