#39.ジョブロックで滞留してた話

はじめに

こんにちはnayaaaaです。
業務で使用しているredisの不調により、本来処理されるはずのジョブが正常に処理されないという事象が発生しため、その際の備忘録として書いてみました。

起きた事象

今回発生した事象として、本来処理されるべきジョブが正常に実行されていませんでした。
過去に処理されるはずだったジョブがDB上でロックされたままとなっており、通常であればこのロックが解除されることでジョブが実行され、処理が行われます。
しかし、以前にRedisの不調が発生していた影響でロックが解除されず、ジョブが滞留していました。
このため、手動でロック情報を削除することで対処を行いました。

実際のコマンドでの確認

# Railsのコンソールを起動する
$ bin/rails c

# Redisに保存されているキーを一覧表示し、状況を確認する
pry(main)> AppName::Redis.keys
=> ["resque:your-app-name_development:stat:processed:worker-1",
    "cache_key__abc123",
    "cache_key__def456",
    "resque:your-app-name_development:workers",
    "resque:your-app-name_development:worker:worker-1:started",
    "resque:your-app-name_development:queues",
    "resque:your-app-name_development:stat:processed"]

# Resqueが管理しているキュー名の一覧が保存されたSet型のキーのデータタイプを確認
pry(main)> AppName::Redis.type "resque:your-app-name_development:queues"
=> "set"

# 現在登録されているキュー名の一覧を取得する
pry(main)> AppName::Redis.smembers "resque:your-app-name_development:queues"
=> ["default_queue", "mailer_queue", "heavy_lifting_queue"]

# 問題となっているジョブのキュー（problem_job_queue）が一覧にないため、手動でSetに追加する
pry(main)> AppName::Redis.sadd("resque:your-app-name_development:queues", "problem_job_queue")
=> true

# キュー名が正しく追加されたか再度確認する
pry(main)> AppName::Redis.smembers "resque:your-app-name_development:queues"
=> ["problem_job_queue",
    "default_queue",
    "mailer_queue",
    "heavy_lifting_queue"]

# 一旦コンソールを抜けてログを確認するなどやってみる
pry(main)>
[1]+  Stopped                 bin/rails c
$ less log/resque_problem_job.log
$ fg
bin/rails c

# 問題のジョブを投入し、システム本来の自動登録機能をトリガーする
pry(main)> ProblemJob.perform_async({param: 'some_value'})
=> true

# データベースのjob_locksテーブルを調べて、ロックされているジョブがないか確認する
pry(main)> JobLock.all
=> [#<JobLock:0x...
   id: 101,
   job_name: "ProblemJob",
   lock_name: "{\"param\":\"some_value_alpha\"}",
   created_at: Mon, 21 Jul 2025 03:58:59 UTC +00:00,
   updated_at: Mon, 21 Jul 2025 03:58:59 UTC +00:00>,
  #<JobLock:0x...
   id: 102,
   job_name: "AnotherJob",
   lock_name: "{\"param\":\"some_value_beta\"}",
   created_at: Sun, 20 Jul 2025 05:27:46 UTC +00:00,
   updated_at: Sun, 20 Jul 2025 05:27:46 UTC +00:00>]
  #<JobLock:0x...
   id: 103,
   job_name: "AnotherJob",
   lock_name: "{\"param\":\"some_value_beta\"}",
   created_at: Sun, 20 Jul 2025 06:27:46 UTC +00:00,
   updated_at: Sun, 20 Jul 2025 06:27:46 UTC +00:00>]

# 古いロック（Stale Lock）が3件残っていることをSQLでカウントして確認
pry(main)> JobLock.count
=> 3

# テーブル内のすべてのロックレコードを強制的に削除し、問題を解消する
pry(main)> JobLock.destroy_all
=> [#<JobLock:0x...
    id: 101, ...>,
   #<JobLock:0x...
    id: 102, ...>]
   #<JobLock:0x...
    id: 103, ...>]

# ロックがなくなったことを確認（空のリストが返ってくる）
pry(main)> JobLock.count
=> 0

本来登録されるはずだったキューを手動で登録し、キューにジョブを投入することで、システム本来の自動登録機能がトリガーされるように対応しました。
あわせて、データベースのjob_lockテーブルを確認し、ロックされているジョブが存在しないかを調査しました。
結果として、ロック状態のレコードが削除されたことにより、滞留していたジョブが正常に解消されました。

まとめ

今回の問題点として、以下の点が挙げられるかなと思います。

• 本来登録されるはずのキューが登録されていなかったこと

• 過去にロックされたレコードが存在していたため、ジョブが滞留し、ワーカーによる処理が実行できなかったこと

上司の方に教えていただき、無事に問題を解決することができました。
このような事象はこれまで経験がなかったため、良い学びとなりました。
それでは、ありがとうございました！