This page looks best with JavaScript enabled

アカツキの夏インターンに参加してRailsのログ配信改善に取り組んだ話

 ·   ·  ☕ 7 min read  ·  ✍️ さんぽし

こんにちわ

9/7 ~ 9/25の期間でアカツキのAkatsuki Summer Internship 2020に参加してきました

この記事ではインターン中に取り組んだ内容について紹介したいと思います。

インターン業務内容

今回のインターンでは「ログ配信周りの改善」を中心とする以下のタスクを行いました。

  • 開発環境からログの配信を行えるようにする
  • アクセスログの配信方法の改善
  • RedashにてAthenaからアクセスログの解析

既存のログ配信環境に関して

既存のログ配信の構成は以下のようになっていました

既存のログ配信環境

  1. appコンテナがアクセスログをアプリケーションログ内に吐く
  2. Volumeを通してfluentdがtailする形でアクセスログのみを収集、またKPI分析などの特別な目的で利用する情報は別途直接fluentdに送られる
  3. fluentdはログを分類し、アクセスログは直接複数のS3へ、KPIログなどはAggregatorに配信
  4. Aggregatorはさらにそれを複数のRDSやS3に対して配信

という流れになっています。

開発環境からログの配信

プロジェクトにはローカルに立ち上げることができる開発/検証用の環境が存在しています。
既存ではdocker-composeを利用してapp・MySQL・Redis・memcachedが立ち上がるようになっていました。

既存のログ配信環境

※ログ配信に関係のないRedis, memcachedを省略

現状の問題点として、ここにログ配信周りの環境が含まれていないことにより、

  • ログの出力に関わる開発を行った際にKPIログなどが行き着く先のRDSの型などの検証ができない
  • 今回僕がやるようなfluentd自体を絡めた開発の検証ができない

と言った点がありました

そこで環境にfluentdのコンテナを新たに追加し、アプリケーションから手元のfluentdを通して開発用S3へログを配信する変更を加えました。

ざっくり変更後の検証環境の構成図です

既存のログ配信環境

※ログ配信に関係のないRedis, memcachedを省略

また、図にあるように、すでに存在するMySQLにKPIログの記録用のDBを作成し、RDSに投げ込まれるログをこの環境ではMySQLに向けることでRDSを絡めた開発の検証にも対応しました。

ちなみに、S3へのUploadを行う際の認証はshared_credentialsのオプションを利用し、手元の~/.aws/credentialsをコンテナ内にマウントすることで行いました。

アクセスログの配信方法の改善

アクセスログの既存の配信方法は

  • アプリケーションコンテナがファイルにアクセスログを吐く
  • volumeを通してfluentdコンテナがtailする
  • fluentdでアクセスログのみをうまくgrepして抽出し、S3などに配信する

と言った仕組みになっています。

これによる問題点として以下のような点があります。

  • 同時に膨大な数のアプリケーションコンテナが同一のログファイルに書き込むためなのかごく稀にログが壊れている
  • fluentdにてアプリケーションログからアクセスログのみをgrepするのが非効率 and 稀に不正確

改善策としてはシンプルにforwardしているfluentdに対してKPIログなどとは別のポートを通して直接ログを送りつける形に変更しました。

以下変更後の構成図です

既存のログ配信環境

既存のアクセスログの出力にはlogrageを利用していました

roidrage/lograge - GitHub

アクセスログに求められる要件は以下の通りです

  • 既存のlogrageが出しているログの内容はそのまま欲しい
  • アプリケーションログファイルへのアクセスログの出力は残しておきたい
  • 500が帰った際などのexceptionなど追加で欲しい情報がある。また、POSTパラメータをJSONシリアライズしたいなど、logrageの内容から少しカスタマイズをかけたい

logrageのloggerとしてfluentdへの出力を行うact-fluent-logger-railsなどのloggerを登録するというのがシンプルな方法だったのですが、logrageのloggerは複数設定できず、アプリケーションログファイルに残しつつfluentdへlogを出力するという要件を満たせませんでした

actindi/act-fluent-logger-rails - GitHub

そのため、logrageはそのままアプリケーションログへの出力を担当させておき、上記の要件をみたすログをfluentdへと送る部分の開発を行いました

この開発には以下のActive Support::Notificationsを利用しました

Active SupportはRailsのコア機能のひとつであり、Ruby言語の拡張、ユーティリティなどを提供するものです。Active Supportに含まれているInstrumentation APIは、Rubyコードで発生する特定の動作の計測に利用できます。

イベントは簡単にサブスクライブできます。ActiveSupport::Notifications.subscribeをブロック付きで 記述すれば、すべての通知をリッスンできます。

Active Support の Instrumentation 機能 - 13 イベントのサブスクライブ

今回はprocess_action.action_controllerをサブスクライブすることでcontrollerの動作の通知を受け取ります。

通知を受けてActiveSupport::Notificationsから渡される情報からログを作成し、公式が出しているfluent-logger-rubyを利用して、fluentdへログを送りました。

fluent/fluent-logger-ruby - GitHub

この方式をとることで、lograge相当のログの情報を残しつつ、ログ内容の改変や追加などを行うことができました。

Redashにてアクセスログの解析

Redashを用いてAthenaからアクセスログの解析を行いました。

Redashはデータ視覚化を行うことのできるサービスでAthenaや BigQueryなどなどのデータにアクセスし、グラフや表などの形で非エンジニアの方も閲覧しやすい形にまとめることができます。

getredash/redash - GitHub

  • 指定したユーザー・日付のアクセスログを時間順に表示する
  • 指定した日付のAPI(path)ごとの呼び出し回数の統計を表示する。グラフで可視化してみる
  • 指定した日付の例外が発生しているアクセスログを時間順に最大1000件まで表示
  • 上記例外が発生した1日のAPIごとの統計をとる

などのクエリを追加しました。

苦労した点

fluentd分からん

頑張りました。

割とシンプルなので助かりました

Rails分からん

Railsを扱った軽い経験は一応ありましたが、最終的に使用したActive Support::Notificationsは存在すらしらず、かなり試行錯誤していました。

ちなみに具体的に他に検討した案&没理由は以下の通りです。

・logrageのcustom_options内で無理やりfluentdにログを飛ばす
→トリッキーなので却下

・ApplicationControllerのbefore_actionにログの出力を行う関数を挟む
→リクエストに対するレスポンス内容などのリクエスト内容以外の情報が取得できず却下。
 また、レスポンス内容は別で出力!とかにしても複数コンテナが書き込むログの中でどのリクエストとレスポンスが紐づくかわからなくなるのでそれも却下

終わりに

今回はシルバーウィークを挟んで3週間という期間でしたが、ログ周辺のシステムを広く触る経験ができたのはとても良い経験でした。ログ配信周りは今まで開発の経験も知見もなく、あまり個人開発では手が回らないような部分なのでとても貴重な経験になったと感じています。

3週間お世話になりました!!!

Share on

さんぽし
WRITTEN BY
さんぽし
Web Developer /w Elixir, Go