Sidekiq のロギングに Rails logger を利用する

動機

Sidekiq は Sidekiq::Logging.logger に設定された Logger を利用し、デフォルトでは普通の Logger となっています。

加えて、デフォルトでは STDOUT への出力ですが、-L オプションや設定ファイルに指定することでファイルへの書き出しも可能です。

Logging - mperham/sidekiq

Sidekiq を Rails と一緒に使っている場合は、Rails.logger と同じものを使いたいケース

Fluentd を使っていたり、特殊なフォーマットを使っている場合に、Rails.logger に設定された logger はなんらか設定が反映された Logger である事もあると思います。

そういう場合に Sidekiq の Logger も設定を同じにできれば、Sidekiq 自身が出力するログもその設定通りになります。

あくまで Sidekiq 自身が出すログに興味があるケースだけですが。

方法

公式の Wiki に基本的なやり方は書いてあります。
Customize Logger - mperham/sidekiq

Rails の場合だと、config/initializer で以下のように書けば良さそうです。

config/initializer/sidekiq.rb

Sidekiq::Logging.logger = Rails.logger

# or

Sidekiq.configure_server do |config|
  config.logger = Rails.logger
end

Sidekiq.configure_client do |config|
  config.logger = Rails.logger
end

一つの Rails アプリで server(daemon 側）と client(perform_async する側） を分けて設定することも可能です。
（client 側で Sidekiq 自身がログを出すケースがあるのかはちょっと分かりませんが。）

Sidekiq が提供する情報も含んだログを出す

単純に Rails.logger に差し替えてしまうと、Sidekiq の元々のロガーが出力していたような job id(JID) 等が得られません。

その場合は以下のような Formatter を作って入れ替えるのも良いかもしれません。

config/initializer/sidekiq.rb

class HogeFormatter < Sidekiq::Logging::Pretty
  def call(severity, time, program_name, message)
    # ここでログのメッセージを定義
  end
end

Rails.logger.formatter = HogeFormatter.new

# Sidekiq::Logging.logger と入れ替え

Sidekiq::Logging::Pretty を継承した Logger にすることで、Thread[:sidekiq_context] に入った情報を利用することができます。

sidekiq/lib/sidekiq/logging.rb

class Pretty < Logger::Formatter
  SPACE = " "

  # Provide a call() method that returns the formatted message.
  def call(severity, time, program_name, message)
    "#{time.utc.iso8601(3)} #{::Process.pid} TID-#{Thread.current.object_id.to_s(36)}#{context} #{severity}: #{message}\n"
  end

  def context
    c = Thread.current[:sidekiq_context]
    " #{c.join(SPACE)}" if c && c.any?
  end
end

上記コードを見て分かる通り、#context を呼び出せばスペースで区切られた文字列を直接利用することも可能です。

Thread.current[:sidekiq_context] の内容は

デフォルトの Pretty Formatter が出すログは以下のようなものですが、その内の HogeWorker JID-bda742542c60e10e4423e944 の部分ですね。Job Id(JID) と Worker の class 名です。

2016-10-06T04:07:04.705Z 68527 TID-oxs3ft3jg HogeWorker JID-bda742542c60e10e4423e944 INFO: start
2016-10-06T04:07:04.924Z 68527 TID-oxs3ft3jg HogeWorker JID-bda742542c60e10e4423e944 INFO: done: 0.219 sec

コードを見ると BID も存在すれば出すようなので、Sidekiq::Batch も見越したコードのようです。

sidekiq/lib/sidekiq/middleware/server/logging.rb

def log_context(worker, item)
  klass = item['wrapped'.freeze] || worker.class.to_s
  "#{klass} JID-#{item['jid'.freeze]}#{" BID-#{item['bid'.freeze]}" if item['bid'.freeze]}"
end

例えば特別なログを出す Sidekiq middleware を作る

そういうケースにおいて、Sidekiq の Logger をアプリ側の Logger に合わせておけば、いきなり middleware の内部で Rails.logger と呼ばずに済んでよいですね。