ActiveJobの処理が時々コケることがあったので調査した。
Active Job の基礎 - Railsガイド を参照したところ、ActiveJobのコールバックは以下のようになる。
- before_enqueue
- around_enqueue
- after_enqueue
- before_perform
- around_perform
- after_perform
問題のあったコード
そして、元々のコードはこういう感じのことをやっていた。TaskLogモデルがあったとする。
- キューに入った時点でTaskLogモデルを作成する
- TaskJob実行直前に、ジョブIDからタスクログを取得してステータスを処理中に変更
- 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
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
end
end
まとめ
enqueue系のコールバックは、使うにしても「予約しました」とか、そういう通知系をやるくらいに留めておく。perform系の処理で参照したいような前処理をenqueue系でやるべきではない！
