Sidekiq のジョブの内容をログに出力する
Sidekiq を使っていると、ジョブにどのような引数が渡されているかを知りたいときがあります。 必要なキューにのみログを仕込んでもよいのですが、Sidekiq のロガーを上書きすることで、ジョブの内容をログに出力することができます。
以下は、ロガーを上書きする前のログです。
2018-08-17T01:20:52.450Z 7286 TID-ouz91zswg FooBarWorker JID-f1558334f278e0c63f879c14 INFO: start
2018-08-17T01:20:52.517Z 7286 TID-ouz91zswg FooBarWorker JID-f1558334f278e0c63f879c14 INFO: done: 0.068 sec
ロガーを上書きするには、config/initializers/sidekiq.rb
を以下のように変更します。
class JobLogger < Sidekiq::JobLogger
def call(item, queue)
Sidekiq::Logging.with_context("source=#{item}") do
super(item, queue)
end
end
end
# 必要な処理のみ書いています
Sidekiq.configure_server do |config|
config.options[:job_logger] = JobLogger
end
Sidekiq::JobLogger
というのはデフォルトのロガーで、
そのクラスを継承して自前のロガーを実装しています。#call
メソッドの item
には例えば、クラス名 (class
)、引数 (args
)、ジョブの作成日時 (created_at
) などが入った Hash が入ってきます。
{
"class"=>"FooBarWorker",
"args"=>[{"id"=>765}],
"retry"=>true,
"queue"=>"foo_bar",
"jid"=>"050f2d6c412e73b48c3b57d5",
"created_at"=>1534469654.951613,
"enqueued_at"=>1534469654.951725
}
Sidekiq::Logging.with_context
で、ログに追加したい情報を渡せます。item
を指定し、デフォルトのロガーをラップしています。
引数のみでよければ item['args']
を指定します。
この状態で再びキューを追加してみると、以下のようにログが書き換わっていることがわかります。
2018-08-17T01:34:14.953Z 9944 TID-ovh7sebo4 FooBarWorker JID-050f2d6c412e73b48c3b57d5 source={"class"=>"FooBarWorker", "args"=>[{"id"=>765}], "retry"=>true, "queue"=>"foo_bar", "jid"=>"050f2d6c412e73b48c3b57d5", "created_at"=>1534469654.951613, "enqueued_at"=>1534469654.951725} INFO: start
2018-08-17T01:34:15.691Z 9944 TID-ovh7sebo4 FooBarWorker JID-050f2d6c412e73b48c3b57d5 source={"class"=>"FooBarWorker", "args"=>[{"id"=>765}], "retry"=>true, "queue"=>"foo_bar", "jid"=>"050f2d6c412e73b48c3b57d5", "created_at"=>1534469654.951613, "enqueued_at"=>1534469654.951725} INFO: done: 0.738 sec
ログのサイズは増えるので、ご利用は計画的に。
今回の実装は、シンプルにラップしているだけなので、ジョブが終了した場合にも item
が出力されます。
気になる場合は Sidekiq::JobLogger
を参考に実装するとよいでしょう。
Sidekiq の Wiki では、ロガーを上書きする方法以外にも、ロガーのフォーマット(2018-08-17T01:34:14.953Z 9944 TID-ovh7sebo4 FooBarWorker JID-050f2d6c412e73b48c3b57d5
の部分) を
カスタマイズする方法についても触れられています。