概要

とある Rails プロジェクトでバックグラウンドジョブに Delayed::Job を利用しています。
いやー、本当に便利ですよね、Delayed::Job。

しかし、この Delayed::Job でハマった点があったので共有しようと思います。

問題

一部のジョブが正しく動いていない気がするんです…。
気がするというのは、通常ジョブの実行時にエラーが発生した場合は
delayed_jobs テーブルの last_error カラムにエラーの内容が入った状態でレコードが残るはずなのですが、今回はレコードが残っていないのです。
しかし、処理が正常に完了した形跡がない。

この時の Delayed::Job のログはこんな感じです。

[Worker(host:niko.local pid:1234)] Job NikoYazawaService#execute (id=251) RUNNING
[Worker(host:niko.local pid:1234)] Job NikoYazawaService#execute (id=251) COMPLETED after 2.5252
[Worker(host:niko.local pid:1234)] 1 jobs processed at 0.2521 j/s, 0 failed
[Worker(host:niko.local pid:1234)] Job Delayed::PerformableMethod (id=252) RUNNING
[Worker(host:niko.local pid:1234)] Job Delayed::PerformableMethod (id=253) RUNNING

そこで、原因調査のために手動で任意のジョブを実行してみました。
Rails コンソール上で Delayed::Backend::Base#invoke_job メソッドを叩くことで実行します。

Delayed::Job.find(252).invoke_job

Delayed::DeserializationError: ActiveRecord::RecordNotFound, class: User, primary key:  (Couldn't find User without an ID)

なんだこれは！エラーが起きてるじゃないか！

原因

原因はまさに DelayedJob に ActiveRecord インスタンスを渡す時の注意という記事に書かれている通りです。
この記事がなかったら原因究明にもっと時間がかかっていたと思います。@kuboon さんに圧倒的感謝。

非同期処理の実行対象となるオブジェクトで永続化されていない ActiveRecord オブジェクトを保持していたことが原因でした。

class User < ActiveRecord::Base
  def leader?
    name == '高坂 穂乃果'
  end
end

class NikoYazawaService
  def initialize(user: nil, name: nil)
    @mock_user = user || User.new(name: name)
  end

  def execute
    # do something with @mock_user
  end
end

Delayed::Job は handler カラムの YAML 文字列をデシリアライズする際、
オブジェクトが ActiveRecord オブジェクトだった場合は id からロードしています。
そのため @mock_user に永続化されていないオブジェクト (つまり id が nil) が代入された場合に ActiveRecord::RecordNotFound エラーが発生していたわけですね。

対応

今回のケースでは @mock_user を遅延初期化することで解決できました。

class NikoYazawaService
  def initialize(user: nil, name: nil)
    @mock_user = user
    @name = name
  end

  def execute
    # do something with mock_user
  end

  private

  def mock_user
    @mock_user ||= User.new(name: @name)
  end
end

その他の対応方法としては、
永続化されていない ActiveRecord オブジェクトをモックとして利用しているのであれば
代わりに Struct (OpenStruct) などを利用する等でしょうか。

ちなみに対応後の Delayed::Job のログはこんな感じです。

[Worker(host:niko.local pid:2345)] Job NikoYazawaService#execute (id=251) RUNNING
[Worker(host:niko.local pid:2345)] Job NikoYazawaService#execute (id=251) COMPLETED after 2.5252
[Worker(host:niko.local pid:2345)] Job NikoYazawaService#execute (id=252) RUNNING
[Worker(host:niko.local pid:2345)] Job NikoYazawaService#execute (id=252) COMPLETED after 3.5353
[Worker(host:niko.local pid:2345)] Job NikoYazawaService#execute (id=253) RUNNING
[Worker(host:niko.local pid:2345)] Job NikoYazawaService#execute (id=253) COMPLETED after 4.5454

Job Delayed::PerformableMethod (id=xx) RUNNING という行がなくなり、
それぞれのジョブがちゃんと RUNNING → COMPLETED と表示されるようになりました。

まとめ

永続化されていない ActiveRecord オブジェクトを持ったオブジェクトをジョブに登録すると ActiveRecord::RecordNotFound エラーになる。
- 永続化されていても、例えばジョブ実行時にレコードが削除されている場合も同様の問題が起きる。
デジリアライズ時にエラーになってもジョブはエラーを残さない。
Delayed::Job のログを確認して、各ジョブの状態が正しく RUNNING → COMPLETED と遷移しているか確認する。
- Job Delayed::PerformableMethod (id=xx) RUNNING が表示されている場合はあやしい。

永続化されていない ActiveRecord オブジェクトを利用する処理を Delayed::Job で実行する場合は注意せよ！

概要

問題

原因

対応

まとめ

参考