Fargate上のRailsからJSON形式でログをrequest_idと一緒に出力

この記事は ZOZO テクノロジーズ #2 Advent Calendar 2020 の22日目の記事です。

AWS ECS FargateでRailsを動かす場合はログをJSON形式に出力することが多いと思います。
いくつか手段がある中で自分の職場ではlogrageを使っているんですが、悩ましいことがありました。

試行錯誤の末、解決する手段が分かったのでログを残しておきます。

logrageの設定状況
Lograge.loggerの呼び出しで困った
request_id問題
まとめ

logrageの設定状況

本番環境はFargate、開発環境はローカルのマシンなので RAILS_ENV=production な場合だけlogrageを有効化する設定をしています。

# config/environments/production.rb
config.lograge.enabled = true

# config/initializers/lograge.rb
Rails.application.configure do
  config.lograge.formatter = Lograge::Formatters::Json.new
  ...
end

ログがJSON形式で出力されていると人間が読みにくいログになってしまうため開発環境ではlogrageを有効化していないのですが、これによって困ったことが起きます。

Lograge.loggerの呼び出しで困った

通常のアクセスログと違って、任意のタイミングでアプリケーションのログを吐きたい場面があると思います。
一般的には Rails.logger.info('hoge') のような形でログを吐きますが、Fargate上で動かす場合はCloudWatch Logsでの検索も考慮してJSON形式で出力したいわけです。

logrageを使っている場合は Lograge.logger.info('hoge') のようにしてログを出力するんですが、先述の通り開発環境ではlograge無効状態で開発をしているためエラーになります。

# rails console
[1] pry(main)> Lograge.logger.info('hoge')
NoMethodError: undefined method `info' for nil:NilClass
from (pry):1:in `<main>'

とはいえ、こんなロジックは書きたくありません。

if Rails.env.production?
  Lograge.logger.info('hoge')
else
  Rails.logger.info('hoge')
end

また、そもそもロガーの呼び出しをRails.loggerに統一したいという気持ちもあります。新しくチームに加入した人に毎回ロガーについて説明するのはめんどくさいです。

request_id問題

ログをJSONで出力するだけであれば専用のFormatterを用意すればいいんですが、CloudWatch上で検索しやすくするためにログにはActiveSupport::TaggedLoggingの機能を使ってrequest_idを付与したいです。

config.log_tags = [:request_id]

しかしFormatterを自作してしまうとrequest_idがログから消えてしまいます。調べてみると以下の記事を見つけました。

qiita.com

Formatterの中から見える current_tags をパースしてログに付与しています。
記事で紹介されているFormatterに少し手直しを加えた結果が以下です。

class JsonLogFormatter < Logger::Formatter
  include ActiveSupport::TaggedLogging::Formatter

  def call(severity, time, progname, msg)
    log = {
      common_payload: {
        time: time.iso8601(6),
        level: severity,
        progname: progname,
      },
    }

    message = { message: msg }
    if current_tags.empty?
      log.merge!(message)
    else
      tagged = Rails.application.config.log_tags.zip(current_tags).to_h
      log.merge!(tagged, message)
    end
    "#{log.to_json}\n"
  end
end

このFormatterをRails.loggerのformatterとして適用してlogrageと併用
とあるcontollerのactionメソッドに Rails.logger.info({ hoge: :fuga }) を埋め込んだ結果の出力が以下です。

$ rails s
=> Booting Puma
=> Rails 6.0.3.4 application starting in development
=> Run `rails server --help` for more startup options
Puma starting in single mode...
* Version 5.0.4 (ruby 2.6.6-p146), codename: Spoony Bard
* Min threads: 5, max threads: 5
* Environment: development
* Listening on http://127.0.0.1:3000
* Listening on http://[::1]:3000
Use Ctrl-C to stop
{"common_payload":{"time":"2020-12-21T13:29:57.115795+09:00","level":"INFO","progname":null},"request_id":"480595f3-250b-4210-b4fd-2e81da70923d","message":{"hoge":"fuga"}}
... # 以下logrageによるアクセスログか出力