こんにちは！株式会社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の「急成長ベンチャー企業でシステム負債を返すために取り組んできたこと」です

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

rack-action_loggerの機能

課題

導入の仕方

カスタマイズ

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

パフォーマンスは？

最後に