Sidekiq の Middleware を使ってジョブのログを整形する

Published
2023-05-08
Tags
#ruby#sidekiq

はじめに

今回想定する Ruby と Sidekiq gem のバージョンは以下の通り

  • Ruby v3.2.2
  • Sidekiq v6.5.8


問題

Sidekiqワーカーのログは、デフォルトでは標準出力で以下のような形式でログ出力される

2023-04-27 16:53:10 2023-04-27T07:53:10.713Z pid=1 tid=19nx INFO: Starting processing, hit Ctrl-C to stop
2023-04-27 16:53:15 2023-04-27T07:53:15.760Z pid=1 tid=1k8h INFO: queueing SampleJob (sample_job)
2023-04-27 16:53:15 2023-04-27T07:53:15.762Z pid=1 tid=1k91 class=SampleJob jid=471563f0abb0633b58163bc9 args= INFO: start
2023-04-27 16:53:16 2023-04-27T07:53:16.140Z pid=1 tid=1kdh class=SampleAsyncJob jid=e835fa793c5665286dc067a4 args=xxxxx_sample_id INFO: start
2023-04-27 16:53:16 2023-04-27T07:53:16.143Z pid=1 tid=1k91 class=SampleJob jid=471563f0abb0633b58163bc9 args= elapsed=0.38 INFO: done
2023-04-27 16:53:16 2023-04-27T07:53:16.190Z pid=1 tid=1kdh class=SampleAsyncJob jid=e835fa793c5665286dc067a4 args=xxxxx_sample_id elapsed=0.05 INFO: done


しかし、デフォルトのログ形式では以下の問題点がある。

  • ぱっと見でわかりづらい
  • Datadog 側で、ジョブのログを特定のキーでフィルター検索がしづらい
  • ワーカー実行時に渡される引数がある場合、ログに引数は含まれないのでトラブル発生時の調査に必要な情報が不足する


やりたいこと

上記で挙げた問題を解決するため、以下の2点の変更を行うことで解決を図る。

  • ログ出力形式をJSON形式にする
  • Sidekiq Middleware を使用して、ワーカの実行前後に任意の処理を行う


やってみた

Railsを使っている前提ですが、 config/initializers/sidekiq.rb に変更を加える。

特に追加の設定をしていなければ、一般的な sidekiq.rb は以下のような内容になっているでしょう。

# frozen_string_literal: true

require 'sidekiq/web'

redis_config = {
  url: ENV['REDIS_URL'] || 'redis://localhost:6379',
}

Sidekiq.configure_client do |config|
  config.redis = redis_config
end

Sidekiq.configure_server do |config|
  config.redis = redis_config
end

ここから、JSON形式のログとカスタマイズしたログ内容で出力できるようになる変更がこちら

# frozen_string_literal: true

require 'sidekiq/web'

redis_config = {
  url: ENV['REDIS_URL'] || 'redis://localhost:6379',
}

# 自前で用意したログをジョブの実行前後で出力するためのミドルウェア
class CustomLoggingMiddleware
  include Sidekiq::ServerMiddleware

  def call(job, payload, _queue)
    log_data = {
			job_name: job.class.name,
			status: 'START',
			jid: job.jid,
			args: payload['args'],
			start_time: Time.zone.now
		}
    Sidekiq.logger.info(log_data)

    yield

    log_data.merge!(status: 'END', end_time: Time.zone.now)
    Sidekiq.logger.info(log_data)
  rescue StandardError => e
    log_data.merge!(status: 'ERROR', failed_time: Time.zone.now, error_message: e.message, stack_trace: e.backtrace.join("\n"))
    Sidekiq.logger.error(log_data)
    raise e
  end
end

Sidekiq.configure_client do |config|
  config.redis = redis_config
end

Sidekiq.configure_server do |config|
  config.redis = redis_config
	# ログをJSON形式に変更するための設定を追加
	config.log_formatter = Sidekiq::Logger::Formatters::JSON.new
	# Sidekiq Server側に追加した Middleware を適用させる
  config.server_middleware do |chain|
    chain.add CustomLoggingMiddleware
  end
end

この設定でSidekiq の実行ログを見ると以下のようにJSON形式かつワーカー実行時の引数もログに含ませることができる。

2023-04-28 11:09:48 {"ts":"2023-04-28T02:09:48.688Z","pid":1,"tid":"1ke1","lvl":"INFO","msg":{"job_name":"SampleAsyncJob","status":"START","jid":"e4d7dccb97c7e5b8ff5ad6d1","args":["sample_id"],"start_time":"2023-04-28 11:09:48 +0900"},"ctx":{"class":"SampleAsyncJob","jid":"e4d7dccb97c7e5b8ff5ad6d1"}}
2023-04-28 11:09:48 {"ts":"2023-04-28T02:09:48.690Z","pid":1,"tid":"1ke1","lvl":"INFO","msg":{"job_name":"SampleAsyncJob","status":"END","jid":"e4d7dccb97c7e5b8ff5ad6d1","args":["sample_id"],"start_time":"2023-04-28 11:09:48 +0900","end_time":"2023-04-28 11:09:48 +0900"},"ctx":{"class":"SampleAsyncJob","jid":"e4d7dccb97c7e5b8ff5ad6d1"}}

参考