Fargate上のRailsからJSON形式でログをrequest_idと一緒に出力
この記事は ZOZO テクノロジーズ #2 Advent Calendar 2020 の22日目の記事です。
AWS ECS FargateでRailsを動かす場合はログをJSON形式に出力することが多いと思います。
いくつか手段がある中で自分の職場ではlogrageを使っているんですが、悩ましいことがありました。
試行錯誤の末、解決する手段が分かったのでログを残しておきます。
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がログから消えてしまいます。調べてみると以下の記事を見つけました。
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によるアクセスログか出力
Rails.loggerで出力したログにrequest_idを付与することができました。
まとめ
力技感が否めませんがdevelopment, productionの両環境でRails.loggerを利用してログを出力できるようになりました。
しかし以下のように問題点はいくつかあり
- 環境ごとにログのformatterが異なる
- formatterの実装が複雑。
ActiveSupport::TaggedLogging
に詳しくないと厳しい
結局自分がいるチームではrequest_idの自動付与を諦め、JSON出力専用のロガーを実装してすべての環境で共通して使うことにしました。
request_idが欲しければ自分でロガーに渡す使い方です。
その結果ロガーの組み合わせはこうなりました。
環境 | 標準のアクセスログ | 任意のタイミングで吐くログ |
---|---|---|
development | デフォルトのRails.logger | 専用のJSONロガー |
production | lograge logger(JSON Formatter) | 専用のJSONロガー |
コンテナ時代のRails運用はまだまだ試行錯誤が必要そうです。