Sidekiq Worker+Semantic Loggerの構成の際にJob名とJob IDを出す方法

マネーフォワードでSREをしている増田です。普段はSREとしてSLO/SLIの策定やプロダクトのインフラ周りの改善に取り組んでいます。

今回はSidekiq Worker+Semantic Loggerを用いた環境でのJob名とJob IDの取得方法について紹介しようと思います。

問題と初めの目論見

ログの出力は障害等で見ない限り注目することが少なく、普段見逃されがちですが、SRE的にはシステムの状態を把握するために重要な情報の一つです。

SREの活動の一環で、Sidekiqから出力されるログの整理をしていたところ、以下のようにjobの開始と終了の文字列のみしかログに出ていないプロダクトが存在することに気が付きました。

start
done

このログだけではJob IDやJobの名前が分からない為、実行されたJobがどのような物だったのかを特定することが出来ません。

該当のプロダクトはActiveJobではなく、素のSidekiq Worker(正確にはSidekiq 6.3以上なのでSidekiq Jobと呼ばれる物)を使っていた為、当初はSidekiqのlog_formatterの変更で対応しようと考えていました。log_formatterに Sidekiq::Logger::Formatters::JSON.new を指定することで、今まで出力が出来ていなかった、jobのIDやJobの名前を出力することが出来るはずでした。

何故Sidekiqのlog_formatterの変更のみで行けると思ったのか

この部分で設定されるsidekiq_context が rubyのLogger::Formatterクラスを継承したSidekiq::Logger::Formatters::JSONのcallメソッドでctxという変数としてセットされます。Sidekiq::Logger::Formatters::JSON は、この部分でrubyのLoggerクラスにあるformatterとして定義されるので、info等のメソッドを使った場合にjob_id等の情報が取得出来るのではないかと考えました。

Sidekiq Worker + Semantic Loggerの構成の罠

しかし、該当のプロダクトは Semantic Logger を使用していました。そこで、以下のようにSemantic Logger['Sidekiq'] をSidekiqのloggerに設定した上で、log_formatterにSidekiq::Logger::Formatters::JSON.new を割り当てたのですが、この方法では目的のJob ID等のログが出力されずうまく行きませんでした。

Sidekiq.logger = SemanticLogger['Sidekiq']

Sidekiq.configure_server do |config|
  config.log_formatter = Sidekiq::Logger::Formatters::JSON.new
end

詳しく調査を行ったところ、Sidekiq Worker + Semantic Loggerの構成の場合Semantic LoggerではJob IDやJobの名前を正しく出力出来ない場合があることが判明しました。

原因の調査は完全に出来ていないのですが、SemanticLoggerの場合、SidekiqのJobLoggerクラスで行っているsidekiq_contextの内容を取得しようとする仕組みがない為、そのままではjob_id等の情報を取れないことが原因なのではないかと思っています。どちらにせよ、単純にloggerに SemanticLogger を設定するだけではjob_id等の情報を取ることは出来ませんでした。

そこで、Sidekiqのlog_formatterの変更以外の方法でJob IDやJobの名前をログに出力をする方法が無いかを調べた所、SidekiqのCustom Middlewareを使うことでJob IDやJobの名前の情報を出せそうだったので、これを使ってログを出してみることにしました。

SidekiqのCustom Middlewareを使う以外の方法

これは実装後に気がついたことでしたが、LoggerとしてSidekiq::LogggerではなくSemanticLogger['Sidekiq'] を使うのであれば、Sidekiq::Logger::Formatters::JSON で行っている内容を SemantcLoggerの Custom Formatters として定義した上で、SemantcLogger側のformatterとして設定すれば同じ事が出来る可能性があります。しかしながら、この方法を取る場合、今回の実装を捨ててCustom Formatterを使うことになる為、時間の関係上詳しい検証は行いませんでした。

実装

環境は以下になります

Sidekiq Middlewareの使い方についてはこちらを参考にしました。

実装時の環境は以下になります。

今回はJobの開始と終了でログを出したかった為、yield の前後でログを出力するようにしました。具体的な実装としては config/initializers/sidekiq.rb のようなSidekiqの設定が記載されているソースに以下のようなコードを入れました。

class SidekiqCustomLoggerMiddleware
  include SemanticLogger::Loggable

  def call(job_instance, _msg, _queue)
    logger = SemanticLogger['Sidekiq']
    start_time = Time.zone.now
    logger.info('Worker Start', job_name: job_instance.class.name, \
                jid: job_instance.jid, start_time: start_time)
    yield
    finish_time = Time.zone.now
    logger.info('Worker Finish', job_name: job_instance.class.name, \
                jid: job_instance.jid, start_time: start_time, \
                finish_time: finish_time, duration: finish_time - start_time)
  rescue StandardError => e
    failed_time = Time.zone.now
    logger.error('Worker Failed',
                 job_name: job_instance.class.name,
                 jid: job_instance.jid,
                 start_time: start_time,
                 failed_time: failed_time,
                 duration: failed_time - start_time,
                 error_message: e.message,
                 stack_trace: e.backtrace)
    raise e
  end
end

Sidekiq.configure_server do |config|
  config.server_middleware do |chain|
    chain.add SidekiqCustomLoggerMiddleware
  end
end

Sidekiq Middlewareは callというメソッドを持っている任意のクラスです。このクラスをSidekiqのミドルウェアとして登録することで、Jobの実行前後に処理を挟むことが出来るようになります。

Middlewareには Client middleware と Server middleware がありますが、今回はJobが実際にSidekiqで実行される前後のログを取りたかったので、Server middlewareを使います。

Server middleware を使う場合、call メソッドは引数として実行されるJobの情報を第一引数(job_instance)に持っています。このJobの情報をJobの開始、終了、失敗時に SemanticLogger['Sidekiq'] に渡してログを出力するようにしています。 job_instance.class.name でJobの名前を、job_instance.jid でJobのIDを取得することが出来ます。

作成したクラスはSidekiqの設定で、server_middleware に追加する必要があります。 chain.add SidekiqCustomLoggerMiddleware の部分はその登録処理になります。

対応後のログ出力

この対応により、以下のような構造化されたログでJobの情報を出力することが出来るようになりました。

開始のログ

{
  "host": "test",
  "application": "test",
  "environment": "local",
  "timestamp": "2022-07-01T08:14:09.204937Z",
  "level": "info",
  "level_index": 2,
  "pid": 22895,
  "thread": "processor",
  "name": "Sidekiq",
  "message": "Worker Start",
  "payload": {
    "job_name": "SampleWorker",
    "jid": "xfa7aa65bec1a8cddb431d54",
    "start_time": "2022-07-01T08:14:09.204+09:00"
  }
}

終了のログ

{
  "host": "test",
  "application": "test",
  "environment": "local",
  "timestamp": "2022-07-01T08:14:09.211986Z",
  "level": "info",
  "level_index": 2,
  "pid": 22895,
  "thread": "processor",
  "duration_ms": 7.049,
  "duration": "7.049ms",
  "name": "Sidekiq",
  "message": "Worker Finish",
  "payload": {
    "job_name": "SampleWorker",
    "jid": "xfa7aa65bec1a8cddb431d54",
    "start_time": "2022-07-01T08:14:09.204+09:00",
    "finish_time": "2022-07-01T08:14:09.211+09:00"
  }
}

job_nameに SampleWorker というJobの名前が、jidに xfa7aa65bec1a8cddb431d54 というJob IDが出力されています。 JSONで構造化されたログにより、Datadog等のツールを使ってログを簡単に検索/解析することが出来るようになりました。

終わりに

今回はSidekiqの機能を使って、SemanticLoggerを用いてSidekiqのJob IDやJobの名前をログに出力する方法を紹介しました。

マネーフォワードでは、SRE的な視点からプロダクトの開発をサポートして行きたいエンジニアを募集しています。

株式会社マネーフォワード SRE の求人一覧

マネーフォワードでは、エンジニアを募集しています。ご応募お待ちしています。

【会社情報】 ■Wantedly ■株式会社マネーフォワード ■福岡開発拠点 ■関西開発拠点（大阪/京都）

【SNS】 ■マネーフォワード公式note ■Twitter - 【公式】マネーフォワード ■Twitter - Money Forward Developers ■connpass - マネーフォワード ■YouTube - Money Forward Developers

Money Forward Developers Blog

株式会社マネーフォワード公式開発者向けブログです。技術や開発手法、イベント登壇などを発信します。サービスに関するご質問は、各サービス窓口までご連絡ください。