はじめに

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自体の設定は、各自よしなにして下さい。

config/initializers/lograge.rb

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 があれば紐付け可能。

config/environments/development.rb

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形式にしたいだけなんですが、なんでこんなにめんどくさいんでしょうか？
もっとマシな解決方法を知ってる人がいたら教えて下さい。

logrageではRails.loggerのログ出力がJSON形式にならない問題

はじめに

解決策

おわりに