Railsアプリケーションのログを構造化してDatadogで活用するまで

こんにちは、Plex Job開発チームの種井です。私の所属するPlex Job開発チームでは、監視ツールとしてDatadogを使用しています。 Datadogには収集したログを監視や調査に活用する上で便利な機能がいくつかありますが、それぞれの機能を有効化するにはログを予め要求されるフォーマットで書き出す必要があります。今回は、ログをフォーマットすることで、Datadogの各機能を有効化し監視や調査業務に活用するまでの取り組みについて書きたいと思います。

前提
背景や課題
今回のゴール
1. アプリケーションのログを構造化ログにする
- rails_semantic_loggerの導入
- 注意すべき点
2. ログベースのエラートラッキングを有効にする
取り組んでみて
おわりに

前提

Plex Job のバックエンドアプリケーションは Google Cloud 上の GKE(k8s)サービスでホストされています
バックエンドアプリケーションはコンテナ化された Rails アプリケーションが動作しています
監視ツールとして、Datadog を使用しています
この記事ではバックエンドアプリケーション(Railsアプリケーション)から出力されるログについて扱います

背景や課題

まずはじめにログについて少し整理しておきたいと思います。

ログとは？

基本的には連続した文字列のことで、(可能なら)いつイベントが発生したのかを示すタイムスタンプが関連づけられたものです。

引用: 入門監視より

構造化ログと非構造化ログ

ログはさらに構造化ログと非構造化ログに分類されます。

構造化ログ

各フィールドについて、key,value で明確にマッピングされているもの(JSONなど)
機械が解釈しやすい形式

以下は例

{"time_local":"25/Nov/2024:12:16:42 +0000","remote_addr":"192.168.65.1","remote_user":"","request":"GET / HTTP/1.1","status":"200","body_bytes_sent":"615","http_referer":"","http_user_agent":"curl/8.6.0"}

非構造化ログ

各フィールドについて、key,value で明確にマッピングされていないもの
人間が解釈しやすい形式

以下は例

192.168.65.1 - - [25/Nov/2024:11:05:07 +0000] "GET / HTTP/1.1" 200 615 "-" "curl/8.6.0" "-"

構造化ログは監視ツールやプログラムからログを参照したい場合など、ツールで構造化されていることが要求されたりパースが容易ということもあるため、便利に使うことができます。逆にローカル環境での開発時は目視によるログの確認を行うことが多いかと思います。そういった場合は非構造化ログの方が使い勝手がよかったりします。

ログの用途

ログの用途については様々なものがありますが、大きくは以下に分類されます。

監視
- 障害やパフォーマン上のボトルネックの検知
調査
- 不具合やパフォーマンス低下の原因特定
分析
- データ分析によるプロダクトの改善
義務
- 監査ログなど法務観点で定められているログ

参考: https://developer.hatenastaff.com/entry/2020/08/06/110000

Plex Jobでの課題

ログについて整理したところで、課題についてお話ししてきます。

当時のPlex Jobでは、APM機能は有効化されており、トレース情報に基づくエラートラッキングなどの機能については活用できている状態でした。ログについては、監視ツール(Datadog)に送信・収集されているものの、不具合時に関連しそうなログを検索してみる、程度の活用しかされていませんでした。システム規模の拡大や外部システムとの連携の増加により、「監視」や「調査」業務における情報源を増やし活用していきたいというニーズがありました。

当時、送信しているログが非構造化ログになっており

など、「監視」、「調査」業務上で有用な機能が有効化されていませんでした。

今回のゴール

アプリケーションのログを構造化ログにする
ログベースのエラートラッキングを有効にする

ログを構造化し、Datadogやプログラムから活用することを目標としました。

1. アプリケーションのログを構造化ログにする

Railsアプリケーションから出力されるログを構造化ログに対応させます。

メンテナンスが継続的にされている
インストールするだけでRails.loggerを上書きしてくれるため、今後Rails8.1で構造化ログがサポート(https://github.com/rails/rails/issues/50452)された場合に切り替えがしやすそうなこと
Rackなどのミドルウェアで出力されるログもよしなに構造化してくれる

などを理由に、今回はrails_semantic_logger gemを使うことにしました。

以下は、その他に検討した実装方法となります。

Formatterをカスタマイズして、ActiveSupport::Loggerに設定する

formatterをカスタマイズして、構造化ロギングに対応させる方法もありましたが

json形式への変換
ログへのタグ付け
Railsの各コンポーネント(ActiveRecordやActiveJobなど)から出力される各種フォーマットのログへの対応

などを自前でメンテナンスしていくのは大変なので、すでにそういったgemがあれば活用したいという背景がありました。

Logrageを使用する方法

DatadogのドキュメントではLograge gemの使用が推奨されていましたが、メンテナンスが滞っていることもあり、今回は使用を見送ることにしました。

rails_semantic_loggerの導入

Gemfileに以下を追記して、インストールします。

gem 'rails_semantic_logger'

bundle install

インストールするだけで、Rails.loggerがrails_semantic_loggerにより上書きされ、構造化されたログが出力されるようになります。

注意すべき点

導入を進める上で、ローカルのdevelopment環境では構造化されたログが出力されるが、検証環境や本番環境でログが出力されないという現象にぶつかりました。

マルチプロセス環境で Semantic Logger を動かす場合は、子プロセスがフォークされた際にSemantic Logger のスレッドを再起動する必要があります。 RAILS_ENV=productionな環境ではPumaをCluster Modeで起動していたので、config/puma.rbに以下を追記することで解決することができました。

...

on_worker_boot do
  SemanticLogger.reopen
end

...

参考: https://github.com/reidmorrison/semantic_logger/blob/master/docs/forking.md

2. ログベースのエラートラッキングを有効にする

Datadogのエラートラッキング機能は、予め指定されたスキーマの構造化データから自動でエラーを検知して、issueとしてエラートラッカーに起票してくれる機能です。

この機能を有効化するには

kind,message,stack の3つの属性がerror属性配下に存在している
ログのlevel 属性がERROR, CRITICAL, ALERT, or EMERGENCY である

必要があります。

{
  ...
  "level": "ERROR",
  "error": {
    "kind": "...",
    "message": "...",
    "stack": "...",
  }
  ...
}

参考: https://docs.datadoghq.com/ja/logs/error_tracking/backend/?tab=serilog#attributes-for-error-tracking

Semantic Logger標準のログのスキーマには、上記のerror属性に該当する属性は用意されていないため

named_tag やpayload などのカスタム属性用のフィールドに上記の属性を定義しておく
Datadogのログパイプラインで、Remapperプロセッサーを作成して、key/valueをマッピングし直す

ことにしました。

{
  ...
  "named_tags": {
    "kind": "...",
    "message": "...",
    "stack": "...",
  },
  ...
}
// ↓Remap
{
  ...
  "error": {
    "kind": "...",
    "message": "...",
    "stack": "...",
  }
  ...
}

上記の設定を行い、logger.errorでログレベルがERRORのログを出力することで、エラートラッキング機能で該当するログが認識されるようになりました。

取り組んでみて

アプリケーションのログを構造化ログにする
ログベースのエラートラッキングを有効にする

上記の取り組みを経て、「監視」と「調査」業務へのログ活用を進めることができました。

監視
- ログベースのエラー検出ができるようになり、Datadog 上で issue が起票されるようになった
- ログを起点にしたエラー通知などに活用することができるようになった
調査
- ログが構造化されたことにより、Live Search 機能やスクリプトからのログの検索性が改善された
- 構造化ログに対応したことで、Datadog がAPMのトレースとログを紐づけてくれるようになった

おわりに

今回の取り組みを通じて学んだことについて、書き残しておきます。

本番環境で書き出すログは構造化ログにしておく
ツールやプログラムが要求するスキーマに合わせてログを正しくフォーマットする

最後にはなりますが、Plex Jobだけでも今回のような監視や可観測性をはじめコスト最適化などの課題があったり、他事業部のプロダクトもGCPへのインフラ移行を控えていたりします。このような課題にチャレンジしていただけるSREをはじめ、ソフトウェアエンジニア、フロントエンドエンジニアを募集しています。

dev.plex.co.jp

少しでも興味を持っていただけた方は業務委託や副業からでも、ぜひご応募いただけると幸いです。