LITALICO Engineers Advent Calendar 2016 19日目

Railsでのサーバサイドログ収集に悩むあなたに送る - 分析・デバッグ用が捗るrack-action_loggerというgemを作った話

8
いいね
0
コメント

wapa5pow

2016年12月19日に更新

こんにちは！株式会社LITALICOでエンジニアをしております石田です。
『LITALICO Engineers Advent Calendar 2016』 19日目の記事となります。

前回は、ナウでイケてる格安の分析基盤&BIツールをGoogle sheetsを中心に構築した話を書きました。
その際に、サーバ側の、「ユーザ行動ログ」に関しては次回の記事でとなっていたので、この記事で紹介させていただきます。

スマフォアプリ・ゲームを開発する際にユーザの行動ログを取得するために、Rails用のgemであるrack-action_loggerを作りました。

まだまだ完成したばかりなのですが、一部サービスの本番に投入しています。

rack-action_loggerの機能

このgemを導入することにより、「リクエストとレスポンスのヘッダ・ボディや付随する情報」、「データベースの挿入・更新・削除ログ」、「任意のコードの場所に任意のハッシュ値ログ」を、リクエストごとに一意なリクエストIDが紐付けられた形として、標準出力やFluentdに出力できます（出力される関数はカスタマイズ可能なので任意の出力先にすることも可能)。最終的なログの出力先としては、Fluentdを通してBigQueryにログを流すことを想定しています。

Railsではリクエストごとに固有のリクエストIDが付与されますが、その値をすべてのログに紐付ける事によりリクエストごとの値の追跡がBigQueryでSQLのJOINクエリを使って簡単に出来るようになってます。

以下に、この機能を使って解決したかった課題を書きます。

課題

開発時に、以下のような要求があるのですが、簡単に解決できるgemが見つかりませんでした。

ローカルでアプリ開発時にクライアントからサーバへのリクエスト・レスポンスのヘッダ・ボディーなどを簡単にみたい
BigQueryにアクセスログやユーザの行動ログを簡単にため分析したい

1の課題は、rack-access-captureを使えば解決しそうでしたが、ボディやヘッダをとるときにカスタマイズしなければいけなかったのと、2も解決したかったので自分で作る事にしました。

前提として、サーバごとの環境は以下で運営することが多いです。

ローカル環境: 手元のMacでの開発。XcodeのiPhoneシミュレータを動かしながら、ローカルで起動しているRailsサーバに向けリクエスト送信。デバッガも簡単につかえるのでブレークポイントを打ちながらの開発もできる
開発環境(development, staging): AWSなどのリモートにある環境。複数のユーザがつなぎにくる
本番環境(production): iTunesやGoogle Playで配布したクライアントアプリがつなぎに来る場所

ローカル開発時はまあいいのですが、開発環境や本番では、ある特定のユーザのリクエストのURLパスやクエリ、そのリクエストでの行動（アイテムが増えたとか)をバグ対応・CS対応・分析時などに参照したいときが多々あります。その際に、このgemを入れると、1つのリクエストで以下のようにログがでます。（ローカル開発時は標準出力に出せ、そのログにはpretty printもかかってます)

// アクセスログ
{
  "message": {
    "path": "/",
    "method": "GET",
    "params": {
      "password": "[FILTERED]"
    },
    "request_headers": {
      "HTTP_VERSION": "HTTP/1.1",
      "HTTP_HOST": "localhost:3000",
      "HTTP_CONNECTION": "keep-alive",
      "HTTP_UPGRADE_INSECURE_REQUESTS": "1",
      "HTTP_USER_AGENT": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.98 Safari/537.36",
      "HTTP_ACCEPT": "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8",
      "HTTP_ACCEPT_ENCODING": "gzip, deflate, sdch, br",
      "HTTP_ACCEPT_LANGUAGE": "ja,en-US;q=0.8,en;q=0.6",
      "HTTP_COOKIE": "xxx"
    },
    "status_code": 200,
    "remote_ip": "127.0.0.1",
    "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.98 Safari/537.36",
    "device": "pc",
    "os": "Mac OSX",
    "browser": "Chrome",
    "browser_version": "54.0.2840.98",
    "request_id": "150a6ac9-0fd9-4a23-a313-d18da1e35911",
    "response_headers": {
      "X-Frame-Options": "SAMEORIGIN",
      "X-XSS-Protection": "1; mode=block",
      "X-Content-Type-Options": "nosniff",
      "Content-Type": "text/html; charset=utf-8"
    },
    "response_json_body": {
    },
    "tag": "action.rack",
    "user_id": 123
  }
}

// モデルログ - モデルが追加・更新・削除されたときに出力
{
  "message": {
    "user_id": null,
    "request_id": "150a6ac9-0fd9-4a23-a313-d18da1e35911",
    "_method": "update",
    "_after:updated_at": "2016-11-18 18:40:15 +0900",
    "_before:updated_at": "2016-11-18 18:33:56 +0900",
    "_after:views": 96,
    "_before:views": 95,
    "tag": "action.model_articles"
  },
  "tag": "action.model_articles"
}

// 任意のログ
{
  "message": {
    "request_id": "150a6ac9-0fd9-4a23-a313-d18da1e35911",
    "value": "with_tag",
    "tag": "action.activities"
  }
}

導入の仕方

githubのrack-action_loggerのInstallationのREADMEをみればいけると思います。簡単にログが追加できるので、分析が捗るかなと思います。

カスタマイズ

configuration.rbのソースコードが設定を担っているのですが、いくつか有用そうなものを紹介します。

emit_adapter: 出力するクラスを指定する。このクラスを変えることにより任意の出力先を選べる。gemについているのは標準出力と、Fluentd向け
tag_prefix: すべてのログにこのタグがプリフィックスとして付きます。Fluentdでタグにより処理を変えるために設定します。
filters: リクエストパラメータやレスポンスパラメータにはセンシティブなデータ（パスワードなど）もあるのでフィルタできるようにしています。
rack_request_blacklist: アクセスログにあるキーで、この設定にはいっているとそのキーは出力からはずされます。例えば、request_headersが入っていたらリクエストヘッダはアクセスログにはでなくなります。とくに本番でレスポンスのボディがはいっているとログが肥大化しやすいし、使わないことも多いので、デフォルトでははずしている項目があります。
rack_metrics: アクセスログの項目を取得しているクラスです。これをカスタマイズすることによりRack内でとれるデータならログに含めることができます。
rack_content_types: この設定にあるコンテンツタイプのみログを取得します。画像のリクエストなどはログから除くためです。

気になるログの量と値段は？

ログの量は以下です。

アクションログ: 1万PVあたり1MBほど
モデルログ: 1万PVあたり1MBほど(場合によると思います)
任意のログ: 1万PVあたり1MBほど(場合によると思います)

例えば1万DAUで、20PV/1DAUだとすると、1日60MBくらいで1ヶ月で2GB弱となります。
以下が値段なので、1ヶ月だと$1いかないくらいです。

* ストレージ
    * $0.01 / GB / 月  # 90日以上更新がないテーブルのストレージ
    * $0.02 / GB / 月  # 上記以外　
* ストリーミングインサート: $0.01 / 200MB

上記は埋め込む任意のログによったりアクセス量によったりするので事前に見積ることをおすすめします。

パフォーマンスは？

NewRelicで見てみたら該当Rack部分でだいたい10msecくらい使ってそうな感じですが、もっと改善できるようなら将来的にしていきたいです。

最後に

今回は、ログ収集が捗るgemを作った話をかきました。
ログ収集は必須でありますが、実装するには面倒なことが多いので、このgemで少しでも改善できたらなと思います。

明日は@ko1の「急成長ベンチャー企業でシステム負債を返すために取り組んできたこと」です

こんにちは！[株式会社LITALICO](http://litalico.co.jp/)でエンジニアをしております石田です。
『[LITALICO Engineers Advent Calendar 2016](http://qiita.com/advent-calendar/2016/litalico)』 19日目の記事となります。

前回は、[ナウでイケてる格安の分析基盤&BIツールをGoogle sheetsを中心に構築した話](http://qiita.com/wapa5pow/items/d51fc699cb133e4fcded)を書きました。
その際に、サーバ側の、「ユーザ行動ログ」に関しては次回の記事でとなっていたので、この記事で紹介させていただきます。

スマフォアプリ・ゲームを開発する際にユーザの行動ログを取得するために、Rails用のgemである[rack-action_logger](https://rubygems.org/gems/rack-action_logger)を作りました。

まだまだ完成したばかりなのですが、一部サービスの本番に投入しています。

# rack-action_loggerの機能

このgemを導入することにより、**「リクエストとレスポンスのヘッダ・ボディや付随する情報」**、**「データベースの挿入・更新・削除ログ」**、**「任意のコードの場所に任意のハッシュ値ログ」**を、リクエストごとに一意な**リクエストID**が紐付けられた形として、標準出力やFluentdに出力できます（出力される関数はカスタマイズ可能なので任意の出力先にすることも可能)。最終的なログの出力先としては、Fluentdを通してBigQueryにログを流すことを想定しています。

Railsではリクエストごとに固有の**リクエストID**が付与されますが、その値をすべてのログに紐付ける事によりリクエストごとの値の追跡がBigQueryでSQLのJOINクエリを使って簡単に出来るようになってます。

以下に、この機能を使って解決したかった課題を書きます。

# 課題

開発時に、以下のような要求があるのですが、簡単に解決できるgemが見つかりませんでした。

1. ローカルでアプリ開発時にクライアントからサーバへのリクエスト・レスポンスのヘッダ・ボディーなどを簡単にみたい
2. BigQueryにアクセスログやユーザの行動ログを簡単にため分析したい

1の課題は、[rack-access-capture](https://github.com/livesense-inc/rack-access-capture)を使えば解決しそうでしたが、ボディやヘッダをとるときにカスタマイズしなければいけなかったのと、2も解決したかったので自分で作る事にしました。

前提として、サーバごとの環境は以下で運営することが多いです。

* ローカル環境: 手元のMacでの開発。XcodeのiPhoneシミュレータを動かしながら、ローカルで起動しているRailsサーバに向けリクエスト送信。デバッガも簡単につかえるのでブレークポイントを打ちながらの開発もできる
* 開発環境(development, staging): AWSなどのリモートにある環境。複数のユーザがつなぎにくる
* 本番環境(production): iTunesやGoogle Playで配布したクライアントアプリがつなぎに来る場所

```json
// アクセスログ
{
  "message": {
    "path": "/",
    "method": "GET",
    "params": {
      "password": "[FILTERED]"
    },
    "request_headers": {
      "HTTP_VERSION": "HTTP/1.1",
      "HTTP_HOST": "localhost:3000",
      "HTTP_CONNECTION": "keep-alive",
      "HTTP_UPGRADE_INSECURE_REQUESTS": "1",
      "HTTP_USER_AGENT": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.98 Safari/537.36",
      "HTTP_ACCEPT": "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8",
      "HTTP_ACCEPT_ENCODING": "gzip, deflate, sdch, br",
      "HTTP_ACCEPT_LANGUAGE": "ja,en-US;q=0.8,en;q=0.6",
      "HTTP_COOKIE": "xxx"
    },
    "status_code": 200,
    "remote_ip": "127.0.0.1",
    "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.98 Safari/537.36",
    "device": "pc",
    "os": "Mac OSX",
    "browser": "Chrome",
    "browser_version": "54.0.2840.98",
    "request_id": "150a6ac9-0fd9-4a23-a313-d18da1e35911",
    "response_headers": {
      "X-Frame-Options": "SAMEORIGIN",
      "X-XSS-Protection": "1; mode=block",
      "X-Content-Type-Options": "nosniff",
      "Content-Type": "text/html; charset=utf-8"
    },
    "response_json_body": {
    },
    "tag": "action.rack",
    "user_id": 123
  }
}

// モデルログ - モデルが追加・更新・削除されたときに出力
{
  "message": {
    "user_id": null,
    "request_id": "150a6ac9-0fd9-4a23-a313-d18da1e35911",
    "_method": "update",
    "_after:updated_at": "2016-11-18 18:40:15 +0900",
    "_before:updated_at": "2016-11-18 18:33:56 +0900",
    "_after:views": 96,
    "_before:views": 95,
    "tag": "action.model_articles"
  },
  "tag": "action.model_articles"
}

// 任意のログ
{
  "message": {
    "request_id": "150a6ac9-0fd9-4a23-a313-d18da1e35911",
    "value": "with_tag",
    "tag": "action.activities"
  }
}
```

# 導入の仕方

[githubのrack-action_loggerのInstallation](https://github.com/wapa5pow/rack-action_logger#installation)のREADMEをみればいけると思います。簡単にログが追加できるので、分析が捗るかなと思います。

# カスタマイズ

[configuration.rb](https://github.com/wapa5pow/rack-action_logger/blob/master/lib/rack/action_logger/configuration.rb)のソースコードが設定を担っているのですが、いくつか有用そうなものを紹介します。

* emit_adapter: 出力するクラスを指定する。このクラスを変えることにより任意の出力先を選べる。gemについているのは標準出力と、Fluentd向け
* tag_prefix: すべてのログにこのタグがプリフィックスとして付きます。Fluentdでタグにより処理を変えるために設定します。
* filters: リクエストパラメータやレスポンスパラメータにはセンシティブなデータ（パスワードなど）もあるのでフィルタできるようにしています。
* rack_request_blacklist: アクセスログにあるキーで、この設定にはいっているとそのキーは出力からはずされます。例えば、request_headersが入っていたらリクエストヘッダはアクセスログにはでなくなります。とくに本番でレスポンスのボディがはいっているとログが肥大化しやすいし、使わないことも多いので、デフォルトでははずしている項目があります。
* rack_metrics: アクセスログの項目を取得しているクラスです。これをカスタマイズすることによりRack内でとれるデータならログに含めることができます。
* rack_content_types: この設定にあるコンテンツタイプのみログを取得します。画像のリクエストなどはログから除くためです。

# 気になるログの量と値段は？

ログの量は以下です。

* アクションログ: 1万PVあたり1MBほど
* モデルログ:  1万PVあたり1MBほど(場合によると思います)
* 任意のログ: 1万PVあたり1MBほど(場合によると思います)

例えば1万DAUで、20PV/1DAUだとすると、1日60MBくらいで1ヶ月で2GB弱となります。
以下が値段なので、1ヶ月だと$1いかないくらいです。

* ストレージ
        * $0.01 / GB / 月  # 90日以上更新がないテーブルのストレージ
        * $0.02 / GB / 月  # 上記以外　
    * ストリーミングインサート: $0.01 / 200MB

上記は埋め込む任意のログによったりアクセス量によったりするので事前に見積ることをおすすめします。

# パフォーマンスは？

NewRelicで見てみたら該当Rack部分でだいたい10msecくらい使ってそうな感じですが、もっと改善できるようなら将来的にしていきたいです。

# 最後に

明日は@ko1の「急成長ベンチャー企業でシステム負債を返すために取り組んできたこと」です

wapa5pow

1268Contribution

Organization

編集リクエスト

この投稿は LITALICO Engineers Advent Calendar 2016 の 19日目の記事です。

18日目の記事: 「エンジニアがやりがいを持って働ける場所」について「SIerよりWeb系だ！」と言う意見を元に元客先常駐COBOLERが考えてみる

PR 社内メールでの情報共有をなくそう - Qiita:Team

Comments Loading...