よりシンプルなジョブが欲しかったため、以下のジョブを定義した。このジョブは正常終了することを想定して記述した。

touch app/models/task_job.rb

class TaskJob
  def enqueue(job)
    puts "TaskJob#enqueue"
  end

  def before(job)
    puts 'TaskJob#before'
  end
  
  def perform
    puts "TaskJob#perform"
  end

  def success(job)
    puts "TaskJob#success"
  end

  def error(job, exception)
    puts "TaskJob#error"
  end

  def failure(job)
    puts "TaskJob#failure"
  end
  
  def after(job)
    puts 'TaskJob#after'
  end  
end

perform メソッドでエラーが起きる場合を想定して BadTaskJob を作成する。

touch app/models/bad_task_job.rb

class BadTaskJob
  def enqueue(job)
    puts "BadTaskJob#enqueue"
  end

  def before(job)
    puts 'BadTaskJob#before'
  end
  
  def perform
    puts "BadTaskJob#perform"
    raise StandardError.new("Failed to process by something.")
  end

  def success(job)
    puts "BadTaskJob#success"
  end

  def error(job, exception)
    puts "BadTaskJob#error"
  end

  def failure(job)
    puts "BadTaskJob#failure"
  end
  
  def after(job)
    puts 'BadTaskJob#after'
  end  
end

ジョブのHookがどのように呼ばれるかについては後ほど触れる。

正常系のジョブとして TaskJob をキューに投入する。投入直後、 TaskJob#enqueue と出力されるのでHookの enqueue を確認できた。

irb(main):001> Delayed::Job.enqueue TaskJob.new
TaskJob#enqueue
  TRANSACTION (0.0ms)  begin transaction
  Delayed::Backend::ActiveRecord::Job Create (0.3ms)  INSERT INTO "delayed_jobs" ("priority", "attempts", "handler", "last_error", "run_at", "locked_at", "failed_at", "locked_by", "queue", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) RETURNING "id"  [["priority", 0], ["attempts", 0], ["handler", "--- !ruby/object:TaskJob {}\n"], ["last_error", nil], ["run_at", "2024-03-10 12:21:55.816135"], ["locked_at", nil], ["failed_at", nil], ["locked_by", nil], ["queue", "default"], ["created_at", "2024-03-10 12:21:55.816158"], ["updated_at", "2024-03-10 12:21:55.816158"]]
  TRANSACTION (0.1ms)  commit transaction
=> 
#<Delayed::Backend::ActiveRecord::Job:0x000000011331fc90
 id: 1,
 priority: 0,
 attempts: 0,
 handler: "--- !ruby/object:TaskJob {}\n",
 last_error: nil,
 run_at: Sun, 10 Mar 2024 12:21:55.816135000 UTC +00:00,
 locked_at: nil,
 failed_at: nil,
 locked_by: nil,
 queue: "default",
 created_at: Sun, 10 Mar 2024 12:21:55.816158000 UTC +00:00,
 updated_at: Sun, 10 Mar 2024 12:21:55.816158000 UTC +00:00>

この時点で delayed_job テーブルにジョブのレコードが存在する。

ジョブワーカー (rake jobs:work をしたターミナル) を確認する。ジョブワーカーは TaskJob のジョブを実行して以下の内容を出力した。

[Worker(host:Suppaman.local pid:56408)] Job TaskJob (id=1) (queue=default) RUNNING
TaskJob#before
TaskJob#perform
TaskJob#success
TaskJob#after
[Worker(host:Suppaman.local pid:56408)] Job TaskJob (id=1) (queue=default) COMPLETED after 0.0012
[Worker(host:Suppaman.local pid:56408)] 1 jobs processed at 200.0000 j/s, 0 failed

上の出力結果からHookの before はperformの前に呼ばれ、performの後にHookの success が呼ばれ、その次にHookの after が呼ばれることがわかった。

なお、performが正常に終了した場合はlib/delayed/worker.rb#L232にある通りジョブのレコードを削除する。

次は異常系のジョブとして BadTaskJob を投入する。Hookの enqueue はTaskJobと同じである。

irb(main):002> Delayed::Job.enqueue BadTaskJob.new
BadTaskJob#enqueue
  TRANSACTION (0.1ms)  begin transaction
  Delayed::Backend::ActiveRecord::Job Create (0.7ms)  INSERT INTO "delayed_jobs" ("priority", "attempts", "handler", "last_error", "run_at", "locked_at", "failed_at", "locked_by", "queue", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) RETURNING "id"  [["priority", 0], ["attempts", 0], ["handler", "--- !ruby/object:BadTaskJob {}\n"], ["last_error", nil], ["run_at", "2024-03-10 12:32:09.683335"], ["locked_at", nil], ["failed_at", nil], ["locked_by", nil], ["queue", "default"], ["created_at", "2024-03-10 12:32:09.683398"], ["updated_at", "2024-03-10 12:32:09.683398"]]
  TRANSACTION (0.1ms)  commit transaction
=> 
#<Delayed::Backend::ActiveRecord::Job:0x0000000108fd5878
 id: 2,
 priority: 0,
 attempts: 0,
 handler: "--- !ruby/object:BadTaskJob {}\n",
 last_error: nil,
 run_at: Sun, 10 Mar 2024 12:32:09.683335000 UTC +00:00,
 locked_at: nil,
 failed_at: nil,
 locked_by: nil,
 queue: "default",
 created_at: Sun, 10 Mar 2024 12:32:09.683398000 UTC +00:00,
 updated_at: Sun, 10 Mar 2024 12:32:09.683398000 UTC +00:00>

ジョブワーカー (rake jobs:work をしたターミナル) を確認する。 BadTaskJob のジョブが実行されると以下の出力がされた。

[Worker(host:Suppaman.local pid:56408)] Job BadTaskJob (id=2) (queue=default) RUNNING
BadTaskJob#before
BadTaskJob#perform
BadTaskJob#error
BadTaskJob#after
[Worker(host:Suppaman.local pid:56408)] Job BadTaskJob (id=2) (queue=default) FAILED (0 prior attempts) with StandardError: Failed to process by something.
[Worker(host:Suppaman.local pid:56408)] 1 jobs processed at 54.2711 j/s, 1 failed

peformでraiseをしているため、Hookの error が呼ばれたのだと思われる。その次にHookの after が呼ばれる。

config/initializers/delayed_job_config.rb に Delayed::Worker.max_attempts = 3 と記述しているため、ジョブワーカーは再試行上限範囲内と捉えて、数分後に BadTaskJob を実行した。そして以下の出力を得た。Hookの流れは前回のジョブ実行時と同じである。

[Worker(host:Suppaman.local pid:56408)] Job BadTaskJob (id=2) (queue=default) RUNNING
BadTaskJob#before
BadTaskJob#perform
BadTaskJob#error
BadTaskJob#after
[Worker(host:Suppaman.local pid:56408)] Job BadTaskJob (id=2) (queue=default) FAILED (1 prior attempts) with StandardError: Failed to process by something.
[Worker(host:Suppaman.local pid:56408)] 1 jobs processed at 119.2037 j/s, 1 failed

さらに数分後にジョブワーカーはジョブを再実行した。そして以下の出力を得た。前回のジョブ実行と異なるのはHook after の後にHook failure が呼ばれた点である。

[Worker(host:Suppaman.local pid:56408)] Job BadTaskJob (id=2) (queue=default) RUNNING
BadTaskJob#before
BadTaskJob#perform
BadTaskJob#error
BadTaskJob#after
[Worker(host:Suppaman.local pid:56408)] Job BadTaskJob (id=2) (queue=default) FAILED (2 prior attempts) with StandardError: Failed to process by something.
[Worker(host:Suppaman.local pid:56408)] Job BadTaskJob (id=2) (queue=default) FAILED permanently because of 3 consecutive failures
BadTaskJob#failure
[Worker(host:Suppaman.local pid:56408)] 1 jobs processed at 132.2751 j/s, 1 failed

上の出力結果から当該ジョブの実行回数が Delayed::Worker.max_attempts に到達した場合、Hookの failure が呼ばれるとわかった。

ジョブをキーに入れると、応答結果に handler を確認でき、値は yaml 形式と推測できる。GitHubにある delayed_job のREADMEを見るとCustom Jobsで述べられているようにジョブオブジェクトが yaml にシリアライズされていることがわかる。おそらくこの yaml 形式のデータはこのあと復元する際に使われるのであろう。

irb(main):001> Delayed::Job.enqueue TaskJob.new
TaskJob#enqueue
  TRANSACTION (0.0ms)  begin transaction
  Delayed::Backend::ActiveRecord::Job Create (0.6ms)  INSERT INTO "delayed_jobs" ("priority", "attempts", "handler", "last_error", "run_at", "locked_at", "failed_at", "locked_by", "queue", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) RETURNING "id"  [["priority", 0], ["attempts", 0], ["handler", "--- !ruby/object:TaskJob {}\n"], ["last_error", nil], ["run_at", "2024-03-11 01:53:50.625303"], ["locked_at", nil], ["failed_at", nil], ["locked_by", nil], ["queue", "default"], ["created_at", "2024-03-11 01:53:50.625341"], ["updated_at", "2024-03-11 01:53:50.625341"]]
  TRANSACTION (0.4ms)  commit transaction
=> 
#<Delayed::Backend::ActiveRecord::Job:0x000000010765b2f8
 id: 3,
 priority: 0,
 attempts: 0,
 handler: "--- !ruby/object:TaskJob {}\n",
 last_error: nil,
 run_at: Mon, 11 Mar 2024 01:53:50.625303000 UTC +00:00,
 locked_at: nil,
 failed_at: nil,
 locked_by: nil,
 queue: "default",
 created_at: Mon, 11 Mar 2024 01:53:50.625341000 UTC +00:00,
 updated_at: Mon, 11 Mar 2024 01:53:50.625341000 UTC +00:00>

そうだとすると、ジョブワーカーを起動する前に TaskJob のクラス名を GoodTaskJob などに変更するとエラーを引き起こすと思われる。そこでクラス名を変更してからジョブワーカーを起動してみる。

rake jobs:work

ジョブワーカーは以下のように Delayed::DeserializationError を出力した。

[Worker(host:MilleCrepes1.local pid:54199)] Starting job worker
[Worker(host:MilleCrepes1.local pid:54199)] Job TaskJob (id=58) (queue=default) RUNNING
[Worker(host:MilleCrepes1.local pid:54199)] Job TaskJob (id=58) (queue=default) FAILED permanently with Delayed::DeserializationError: Job failed to load: undefined class/module TaskJob. Handler: "--- !ruby/object:TaskJob {}\n"

worker.rb#L240の実装を見たが呼び出し可能ならHookの failure を呼ぶようだ。上の確認例ではyamlからオブジェクトに変換できていないため、 failure は呼ばれていない。