ActiveJobのコールバックは2系統に分かれている

ActiveJobの処理が時々コケることがあったので調査した。

Active Job の基礎 - Railsガイド を参照したところ、ActiveJobのコールバックは以下のようになる。

• before_enqueue
• around_enqueue
• after_enqueue
• before_perform
• around_perform
• after_perform

問題のあったコード

そして、元々のコードはこういう感じのことをやっていた。TaskLogモデルがあったとする。

1. キューに入った時点でTaskLogモデルを作成する
2. TaskJob実行直前に、ジョブIDからタスクログを取得してステータスを処理中に変更
3. TaskJobが終了したら、ジョブIDからタスクログを取得してステータスを終了に変更

class TaskJob < ApplicationJob
  
  after_enqueue do |job|
    TaskLog.create!(job_id: job.id, status: :queued)
  end

  before_perform do |job|
    task = TaskLog.find_by! job_id: job.id
    task.status_processing!
  end

  after_perform do |job|
    task = TaskLog.find_by! job_id: job.id
    task.status_finished!
  end

  def perform
    # do something...
  end

end

しかし、いざ実行すると、たまに失敗するときがあった。before_performのTaskLog.find_by!で落ちていた。ここで落ちるということは、TaskLogが作られていないということだ。

実験

after_enqueueが終わる前にbefore_performが実行されることがある、ということだと判断したので、実験用のコードを書いた。

class TestJob < ApplicationJob

  after_enqueue do |job|
    puts "enqueued TestJob. sleep 10..."
    sleep 10
    puts "enqueued TestJob. end"
  end

  before_perform do |job|
    puts "before_perform TestJob. sleep 2"
    sleep 2
    puts "before_perform TestJob. end"
  end

  after_perform do |job|
    puts "after_perform TestJob."
  end

  def perform
    puts "perform!!!"
  end
end

これをrails cで実行した。sleepしているので10秒後にenquequd TestJob. endと出ます。

pry(main) > TestJob.perform_later
enqueued TestJob. sleep 10...
enqueued TestJob. end
Enqueued TestJob (Job ID: 0234b71e-aa4a-4644-b86e-dcf67b40d550) to Sidekiq(default)
=> #<TestJob:0x00007ff599493630
 @arguments=[],
 @executions=0,
 @job_id="0234b71e-aa4a-4644-b86e-dcf67b40d550",
 @priority=nil,
 @provider_job_id="3f7bda026dc435a015d6f81c",
 @queue_name="default">

その頃、sidekiqを実行中のターミナルでは…

2020-10-21T01:36:32.006Z 51089 TID-our2bxzcp TestJob JID-f427b7a69e619b9e45c68371 INFO: start
before_perform TestJob. sleep 2
before_perform TestJob. end
perform!!!
after_perform TestJob.
2020-10-21T01:36:34.027Z 51089 TID-our2bxzcp TestJob JID-f427b7a69e619b9e45c68371 INFO: done: 2.021 sec

早々にbefore_performが実行され、performも呼ばれ、after_enqueueが終わる前に処理が終わった。

ということは、ActiveJobのコールバックのenqueue系とperform系は完全に別々の処理と考える必要がある。

直したコード

before_enqueueでTaskLogモデルを作るのをやめればいい。

class TaskJob < ApplicationJob
  
  before_perform do |job|
    TaskLog.create!(job_id: job.id, status: :processing)
  end

  after_perform do |job|
    task = TaskLog.find_by! job_id: job.id
    task.status_finished!
  end

  def perform
    # do something...
  end

end

まとめ

enqueue系のコールバックは、使うにしても「予約しました」とか、そういう通知系をやるくらいに留めておく。perform系の処理で参照したいような前処理をenqueue系でやるべきではない！