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 # 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系でやるべきではない！
