はじめに
RailsログをJSON形式にしたいだけなんですが、解決方法が意外とめんどくさかったので、ググってたどり着いた誰かのためにメモを残しておきます。
「Railsログ JSON」で雑にググるとlogrageというgemをいれるとよさそうな感じです。
https://github.com/roidrage/lograge
gem入れるだけでバーンといいかんじのJSONになることを期待したのですが、以下の記事に書いてあるとおり、このgemはコントローラのアクセスログや例外しかJSON形式で出ません。
https://qiita.com/amanekey/items/b921ef73d871dac299eb
おもむろに Rails.logger.info("foo") とかしてもJSONにならなくてそのまま出力されちゃう。
つまりこんなかんじ。
{"method":"GET","path":"/","format":"html","controller":"RootPagesController","action":"index","status":200,"duration":1471.86,"view":1429.04,"db":11.39,"level":"INFO","tag":"rails.controller","uuid":"1ecfefb7-7c5e-4bb7-ada8-711e6743a634","ip":"172.20.0.1","time":"2020-07-10T13:42:11+09:00"}
foo
1行目がlogrageが出力するアクセスログ、
2行目が普通にアプリケーション内でおもむろに Rails.logger.info("foo") した場合のログです。
ダメじゃん。
上記の参考記事では最終的にRails.loggerを使用せずに、独自に定義したMyLogger.runという専用のインターフェースを使ってログを出力していました。
しかしながら、既存のコード量が多いと、Rails.loggerを使っている箇所を全部書き換えるなど現実的ではないです。
一方、単純に Logger::Formatter を継承した独自のログフォーマッタを定義してRails.loggerの出力をJSON形式にしても、logrageで出力できるような request_id などのメタデータを付与することができません。
解決策
なんかよい方法はないかとlogrageのissueを漁っていたら以下を見つけました。
要約すると、まず Logger::Formatter を継承した独自のログフォーマッタを定義してRails.loggerの出力をJSON形式にしておきます。次に ActiveSupport::TaggedLogging 経由で request_id などのコンテキストのメタデータをログの本文に付与できるので、ログの本文から request_id などのタグ部分をパースして、JSONを構築しようというハックです。
なるほど。その発想はなかった。
上記のissueのコメントでは、 -> という区切り文字をマジックワードとしてタグの最後に使って、ログの本文(msg変数)からタグ部分とメッセージ部分を分離しているようでしたが、もうちょっと調べると、 Logger::Formatter#call の中で current_tags が見えることに気づいたので、もうちょっとマシに書けそうです。
また上のissueのサンプルコードでは、Rails.loggerの出力全体をJSONにしているので、logrageが生成するJSON形式のログがmsg変数に入ってきて、JSON in JSONになってしまい若干イマイチです。できれば入れ子のJSONはパースしてマージしたい。
というわけで、もうちょっとマシにしてみたのがこちらです。issueのコメントにも書いてみましたが、若干補足コメント付きで、コードのサンプルをここにも貼っておきます。
手元の環境はRails5.2+lograge v0.11.2です。
class JsonLogFormatter < Logger::Formatter
def call(severity, _time, _progname, msg)
log = {
time: _time.iso8601(6),
level: severity,
progname: _progname,
type: "default",
}
# タグが付いてる場合
unless current_tags.empty?
# タグのkey=valueのmapを作ってマージ
tagged = Rails.application.config.log_tags.zip(current_tags).to_h
log.merge!(tagged)
# msgの先頭に入ってるタグを削除
msg = msg&.split(' ', current_tags.size + 1)&.last
end
begin
# msgがJSON形式の場合は JSON in JSON をフラットにしてマージする
parsed = JSON.parse(msg).symbolize_keys
log.merge!(parsed)
rescue JSON::ParserError
# JSON形式ではない場合は、meessageというkeyに保存
log.merge!({message: msg})
end
log.to_json + "\n"
end
end
lograge自体の設定は、各自よしなにして下さい。
Rails.application.configure do
config.lograge.enabled = true
config.lograge.formatter = Lograge::Formatters::Json.new
config.lograge.custom_options = lambda do |event|
data = {
level: 'INFO',
type: 'access',
}
# customize other fields
# (snip.)
data
end
end
config/environments/*.rb などに定義したログフォーマッタを差し込みます。
付与するタグはコントローラの request 経由で見えるものなら付与できますが、最低限 request_id があれば紐付け可能。
logger = ActiveSupport::Logger.new(STDOUT)
logger.formatter = ::JsonLogFormatter.new
config.log_tags = [:request_id]
config.logger = ActiveSupport::TaggedLogging.new(logger)
Rails.logger.info("foo") のログ
{"time":"2020-07-13T09:57:47.558838+09:00","level":"INFO","progname":null,"type":"default","request_id":"5a48d951-a04b-43fe-b462-f57277b55291","message":"foo"}
logrageのログ
{"time":"2020-07-13T09:57:48.744866+09:00","level":"INFO","progname":null,"type":"access","request_id":"5a48d951-a04b-43fe-b462-f57277b55291","method":"GET","path":"/","format":"html","controller":"RootPagesController","action":"index","status":200,"duration":1675.8,"view":1150.5,"db":15.37,"user_id":null,"params":"{}"}
原理的にlogrageのコンテキストをすべてRails.logger側のログに出力することはできないんですが、最低限request_idがどちらにも含まれていれば、紐付けできるしいいやという作戦です。
おわりに
RailsログをJSON形式にしたいだけなんですが、なんでこんなにめんどくさいんでしょうか？
もっとマシな解決方法を知ってる人がいたら教えて下さい。