Railsのログ集約とCloudWatch Logsによる分析

この記事はSupership株式会社 Advent Calendar 2016の10日目の記事になります。

私はSupershipの所属ではありませんが、同じSyn.ホールディングスのグループ会社である株式会社Socketの @Peranikov と申します。
Socketでは、弊社のプロダクトであるFlipdeskの開発メンバーとしてRubyとScalaに取り組んでおります。

FlipdeskはRuby on Railsで稼働しており、AWS上にインスタンスを立てて運営しております。各インスタンスのログを集約するためにfluentdを使用している方は増えてきているかと思いますが、弊社もご多分に漏れずfluentdを使用しております。今回は、RailsのログをLTSV形式で出力し、fluentdを使ってCloudWatch Logsに集約する方法をご紹介します。

RailsのログをLTSV形式で出力する

Railsが標準で出力するproduction.logなどはマルチラインで出力されるため、このままではfluentdでは少々扱いにくいです。というわけで、rack-ltsv_loggerを使ってLTSV形式に別途ログを出力しています。

rack-ltsv_logger#default-fieldsを見るとこのgemがデフォルトで出力するフィールドがわかりますが、これだけでは運用には不十分なのでさらにフィールドを追加しています。

production.rb

# rack-ltsv_logger settings
class LtsvLogger < ::Logger
  def write(msg)
    @logdev.write(msg)
  end
end

appends = {
  vhost: Proc.new { |env| env['HTTP_HOST'] || "-" },
  ua: Proc.new { |env| env['HTTP_USER_AGENT'] || "-" },
  referer: Proc.new { |env| env['HTTP_REFERER'] || "-" },
  db_runtime: Proc.new { |env| env['action_controller.instance'].try(:db_runtime).to_f / 1000.0 }, # ActiveRecordの実行時間(msecをsecに合わせている)
  view_runtime: Proc.new { |env| env['action_controller.instance'].try(:view_runtime).to_f / 1000.0 }, # Viewの実行時間(msecをsecに合わせている)
  user_id: Proc.new { |env| env['action_controller.instance'].try(:current_user).try(:id) || "-" }, # 自前でControllerに定義したメソッド
  instance_id: Proc.new { |env| ENV['EC2_INSTANCE_ID'] || "-" }, # インスタンスID
}

config.middleware.insert_after(0, Rack::LtsvLogger, LtsvLogger.new('log/rack_ltsv.log'), appends)

env にはRackの環境が格納されており、'action_controller.instance'キーにRailsのControllerのインスタンスが格納されています。
これによりControllerが持つRailsのデータを取得できたり、自前で定義したメソッドを使用したりできます。(これについてはこちらの記事で別途解説しています。)
インスタンスIDも含まれていたほうが便利なので、インスタンス起動時に環境変数EC2_INSTANCE_IDに格納しているものをログにも持たせています。

fluetndによるCloudWatch Logsへの集約

fluetndを用いてのCloudWatch Logsへの転送は特に特別なことはしておらず、input pluginはtailでltsvフォーマットにし、output pluginはfluent-plugin-cloudwatch-logsを使用しています。このプラグインを挟むことで、CloudWatch Logs上ではJSON形式で記録されます。

CloudWatch Logs上での分析

CloudWatch Logsにはログをフィルタリングするためのパターン構文があり、JSONで記録されたログに対して柔軟にフィルタリングすることができます。

例えばこのような形式でログが記録されているとして、
※実際のログから一部省略しています

{
    "pid": 3563,
    "method": "GET",
    "status": 200,
    "reqtime": 1.327199,
    "db_runtime": 0.046870868999999996,
    "view_runtime": 0.01331332,
    "instance_id": "i-58a952d6",
    "time": "2016-12-07T12:01:48+09:00"
}

ActiveRecordの実行時間に5秒以上かかったリクエストを探したい場合、以下のように書けばフィルタリングできます。

{ $.db_runtime >= 5 }

CloudWatch Logsではメトリクスを作成しダッシュボードを作ることも可能なので、フィルタリングと併用しレスポンスが遅いリクエストのグラフを表示することも可能です。

また、CloudWatch Logs単体ではログの集計は行なえませんが、Amazon Elasticsearchと連携させたり、S3にログを出力しておいて、最近発表されたAmazon Athenaを使って集計することも可能かも知れません :)

最後に

RailsのログをLTSV形式で出力し、fluentdでCloudWatch Logsに集約する方法をご紹介しました。CloudWatch Logsのフィルタリングとメトリクスが意外と使えそうだったので、とりあえずログを放り込んでおけば、いざという時の分析に使えるかも知れません。

明日は @hiirokato さんです。よろしくお願いします!