どのリクエストから発生したActiveJobなのかわかるようにしたい

どうも、やっと暖かくなってきたのでユニクロで買った酒蔵Tシャツを着ているエンジニアの大庭です。

www.uniqlo.com

今回はActiveJobがWebのどのリクエストから発生したものなのかを、ログから分かるようにしたかったのでその対応をした話です。

前提

弊社ではRailsのアプリケーションログをlogrageを利用してJSON形式で保存することで、AWS Athenaで検索できるようにしています。 また、ActiveJob(sidekiq)のログも同様に検索できるようにしたかったため、拙作lograge_activejobで出力しています。

困ったこと

エラーの調査時はまだいいのですが、その他の調査時にリクエストとジョブが紐づいていないと調査に手間がかかっていたのでなんとかしたかったです。

どうやって解決するか

X-Rayなど分散トレーシング的な何かを入れた方がいいか？など色々考えていると、ある時ふと思いました。
request_uuidを持ち回せば簡単にトレースできるのでは？🤔

苦労ポイント

request.uuidをThread.current[:request_uuid]のようにControllerで設定すれば、どこからでもrequest_uuidを参照できるようになるのでそれは簡単だったのですが、問題はActiveJob側です。

ActiveJobの実行方法としては、perform_nowとperform_laterの2つがあります。
perform_nowの時はキューに入れずそのままアプリサーバーで同期的に実行するので、Thread.current[:request_uuid]を参照できますが問題はperform_laterです。
perform_laterは非同期なので、アプリサーバーからキューイングでredisに入り、バッチサーバーでredisから取り出して実行するのでThread.current[:request_uuid]は参照できません。（そもそも実行時サーバーが違いますしね。。。
ですので、perform_later時にはもう一工夫が必要でした。

そのperform_nowとperform_laterに対応したのが下記のコードです。

class ApplicationJob < ActiveJob::Base
  attr_accessor :request_uuid

  # perform_nowでは呼ばれない
  before_enqueue :set_request_uuid
  # perform_now,perform_laterどちらも呼ばれる
  # before_enqueueの方が先に呼ばれる
  before_perform :set_request_uuid

  # NOTE: override ActiveJob::Core#serialize
  def serialize
    super.merge("request_uuid" => request_uuid)
  end

  # NOTE: override ActiveJob::Core#deserialize
  def deserialize(job_data)
    super job_data
    self.request_uuid = job_data["request_uuid"]
  end

private

  def set_request_uuid
    self.request_uuid ||= Thread.current[:request_uuid]
  end
end

ActiveJobにもコールバックが用意されているのでそれを利用するのと、 ActiveJobのシリアライズでrequest_uuidを持たせ、デシリアライズで取り出す処理を挟み込みました。

これによってActiveJobをリクエストと紐づけることができるようになりました🎉

さいごに

あしたのチームではエンジニアを募集しています。
ログ基盤などに一過言ある方など、一度お話しでもいかがでしょうか？