Delayed Job のワーカーが突然クラッシュした話

こんにちは。Bizibl で開発エンジニアをしている金井です。
今回は、先日遭遇した「delayed_job のワーカーが単一ジョブの失敗をきっかけにプロセスごと落ちる」というちょっとショッキングな出来事について、原因と学びをまとめます。

事象：ECS タスクで動いていた delayed_job が突然クラッシュ

ある日、ECS 上の delayed_job（DJ）ワーカーコンテナが突然クラッシュしました。
普段なら単一ジョブの失敗ではワーカーが落ちることはなく、「ジョブが失敗 → エラー内容を DB に書き込み → 次のジョブへ」という流れで粛々と動くはずです。

しかし今回は、ワーカープロセスそのものが SIGTERM でも OOM でもなく“異常終了”している。

ログを確認すると──

incompatible character encodings: UTF-8 and ASCII-8BIT

という気になるエラーとともに、ちょうど同じタイミングで Slack API が 500 エラーを返していたことも分かりました。

• ジョブ内で Slack 通知を送る
• Slack API が障害で 500 を返す
• → エラーを拾ってジョブを fail するはずが
• ワーカーごとクラッシュ
• DJを必須コンテナにしていたため、ECSタスクごと再起動

流れとしてはこうなんですが、「え、そんなこと起きる…？」と驚きました。

原因を調査：UTF-8 と ASCII-8BIT の文字コード例外

ログに出ているエラーメッセージは、Ruby/Rails ではしばしば見る “文字コードが混在すると例外が起きる” 系のものですが、
問題は、

なぜこのエラーが delayed_job のワーカープロセス自体を巻き添えにしたのか？

という点です。

調べていくと、とある Issue にたどり着きました。

https://github.com/rails/rails/issues/45418

内容を要約すると：

• エラーオブジェクト内に UTF-8 に変換できないバイト列が含まれている
• delayed_job がこのエラー内容をログとして出力する際に EncodingError が発生
• その例外が handle_failed_job の中で rescue されずに上位へ伝播
• 結果、ワーカープロセスが異常終了

というもの。要は delayed_job 側の不具合みたいです。

delayed_job のソースを確認してみた

問題の挙動を確かめるべく、delayed_job のコードを追ってみました。

■ worker.rb

ジョブ実行の大元は以下：

https://github.com/collectiveidea/delayed_job/blob/v4.1.10/lib/delayed/worker.rb
以下抜粋

def start # rubocop:disable CyclomaticComplexity, PerceivedComplexity
  ...

  say 'Starting job worker'

  self.class.lifecycle.run_callbacks(:execute, self) do
    loop do
      self.class.lifecycle.run_callbacks(:loop, self) do
        @realtime = Benchmark.realtime do
          @result = work_off
        end
      end
    end
    ...
  end
end

ここから以下のように辿っていきます。

work_off
→ reserve_and_run_one_job
→ run
→ rescue Exception (ここでジョブ内のエラーをキャッチ)
→ handle_failed_job (本来ならここで失敗の記録をしてリトライ処理へ)

def handle_failed_job(job, error)
  job.error = error
  job_say job, "FAILED (#{job.attempts} prior attempts) with #{error.class.name}: #{error.message}", 'error'
  reschedule(job)
end

→ job_say
ここが問題のコード。error.message で utf-8 にエンコードできない文字列が入ると incompatible character encodings エラーとなる。
ここで例外が出ると上位の処理では例外をキャッチしてないので、最初の start を実行しているプロセスが異常終了する。

という流れでした。

再現させてみた

先ほどの issue 内で簡単に再現できるコードサンプルがあったので手元でも試してみました。
内容は入力文字列を ASCII-8BIT に強制エンコードしたものをそのままエラーメッセージとして raise するもの。

class TestJob < ActiveJob::Base
  # Thid has no effect on Exceptions thrown in Queue Adapters?
  discard_on Encoding::CompatibilityError
  
  # this will eventually bubble up into the Adapter (when retries exhausted?)
  retry_on Exception, wait: 1.second

  def perform(message)
    raise message.dup.force_encoding("ASCII-8BIT")
  end
end

TestJob.perform_later("🤷")

結果はこうなりました。確かにプロセスごと落ちてる。。

Exception: Encoding::CompatibilityError: incompatible character encodings: UTF-8 and ASCII-8BIT
...
rake aborted!
Encoding::CompatibilityError: incompatible character encodings: UTF-8 and ASCII-8BIT (Encoding::CompatibilityError)
/usr/local/bundle/gems/delayed_job-4.1.13/lib/delayed/worker.rb:274:in `job_say'
/usr/local/bundle/gems/delayed_job-4.1.13/lib/delayed/worker.rb:305:in `handle_failed_job'
...
/usr/local/bundle/gems/delayed_job-4.1.13/lib/delayed/worker.rb:173:in `block in start'
...
Caused by:
🤷
...
/usr/local/bundle/bin/bundle:25:in `<main>'
Tasks: TOP => jobs:work
(See full trace by running task with --trace)
$

もしこれが utf-8 の文字列がそのまま raise されると以下のようにログ出力され、ワーカープロセスは問題なく稼働を続け次のジョブ実行に備えます。

ActiveRecord -- TRANSACTION -- {:sql=>"BEGIN", :allocations=>77, :cached=>nil}
ActiveRecord -- Delayed::Backend::ActiveRecord::Job Update -- {:sql=>"UPDATE `delayed_jobs` SET `delayed_jobs`.`attempts` = 1, `delayed_jobs`.`last_error` = `==raise したエラー文==`", :allocations=>222, :cached=>nil}
ActiveRecord -- TRANSACTION -- {:sql=>"COMMIT", :allocations=>43, :cached=>nil}
[Worker(host:*** pid:152)] 1 jobs processed at 53.5392 j/s, 1 failed
ActiveSupport::Logger -- ]Worker(host:*** pid:152)] 1 jobs processed at 53.5392 j/s, 1 failed

対応策と学び

ひとまず大急ぎで slack api のエラーハンドリングで必ず utf-8 のエラーメッセージを raise するようにしました。
その上で、恒久対応として delayed_job ワーカーを必須コンテナから外し、コンテナ単位の再起動ポリシーを適用しました。
https://docs.aws.amazon.com/ja_jp/AmazonECS/latest/developerguide/container-restart-policy.html

CloudWatch Alarm についても、コンテナ再起動が３回繰り返されたら発報するように設定しました。

今回は Slack の障害と DJ の不具合を同時に踏んで起きた事象でしたが、そもそものコンテナ設計や、外部APIのエラーハンドリング、非同期処理のワーカー選定(プロダクト立ち上げからなんとなく DJ を使っていた)について学びや反省がある一件でした。