Google App Engineで行動ログを記録・収集する方法
Tweet
こんにちは。技術推進室の浅井です。最近tumblrのインターフェイスが変わりましたね。こういうブログ書く場所じゃねーよと言われてる気がして肩身が狭い思いをしています。どきどき・・・
さて、わたくしtwitterのbioにも書いてあるとおりかつてはプログラマーだった時代がありました。
が、最近は行動ログ収集とか集計レポーティングを主な業務としております。PHPから行動ログを出力したり、それをwebサーバー郡から集めてきて集計してレポートするだけの簡単なお仕事ですね。今日はこのへんのお話を。
ログの設計ができたら、まずは行動ログをどこかに書き出すことから始まります。ログを書こうと思ったら、色んな方法があるかと思います。
- ローカルファイルに書く
- RDBやKVSに書く
- fluentd loggerを使う
しかし大事なポイントがあります。
- HTTPリクエストのレスポンスタイムに影響を与えてはならない
- 運用が面倒なことは避けたい
と考えるとローカルファイル最強なわけです。書き込みに失敗するケースなんてそうそうありませんし、1台のwebサーバーでここがネックになるほどのトラフィックはさばかないですし。（書いたものをどう収集するか、という課題が残りますが）
がしかしGAE(/J)です。ローカルファイル出力なんて高尚なことはできませんし、ローカルでfluentdのプロセスを動かしたり、App Engineの外側とソケット通信することすらできません。そしてRDBとKVSは課金されます。
ここをGAE的にはどうすべきかというと、以下のドキュメントに書いてあります。
アプリケーションは、java.util.logging.Logger を使用してアプリケーション ログに情報を書き込むことができます。アプリケーションのログ データを表示、分析するには、管理コンソールを使用します。また、appcfg.sh request_logs を使用してダウンロードできます。管理コンソールは、Logger クラスのログ レベルを認識し、異なるレベルのメッセージをインタラクティブに表示できます。
App Engine は、サーブレットが標準出力ストリーム（System.out）と標準エラー ストリーム（System.err）に書き込むすべてのデータをキャプチャし、アプリケーション ログに記録します。標準出力ストリームに書き込まれた行は「情報」レベルで記録され、標準エラー ストリームに書き込まれた行は「警告」レベルで記録されます。出力ストリームやエラー ストリームにログの書き込みを行うすべてのロギング フレームワーク（log4j など）が動作します。ただし、管理コンソールのログ レベルの表示をより詳細に制御するには、ロギング フレームワークで java.util.logging アダプタを使用する必要があります。
https://developers.google.com/appengine/docs/java/runtime?hl=ja#Logging
要は標準出力に出せ、と。ではこれはおいくらなのかと言うと、Gigabytes per month $0.24だそうで。高いっすね・・・（Amazon S3やGoogle Cloud Storageの2,3倍のお値段です）。そしてそもそも永続化目的ではないので、365日分しか保持できません。（管理画面のApplication Settingsでサイズか日数でlimitをかけてローテーションさせるようになってます）
そして高いとか安いとか以前に、ログを確認する管理コンソールがもっさりしてて使えないし、APIがリクエストログと一体化していて非常に扱いづらいです。
というわけでCloud Storageに持っていきます。
App Engineのcronからこんな感じでログ取りに行き、Cloud Storageへ書き込みます。ActivityLogger.STDLOG_PREFIXで始まるログが行動ログです。（標準出力しか使えないからこういう分け方するしかない）
これがいい感じに動くかというと、そんなことはなく。ログがある程度でっかくなるとダメでした。（もっとしっかり書けばあるいは・・・）
あとlog storageのバックエンドはdatastoreらしく、こいつのレイテンシのスパイクに応じて失敗します。datastoreはいつもスパイクしてます。
cron使ってApp Engine内で処理するのは諦めました。悔しいですが外部CPUリソースを使いましょう。
前述のコードにあるlog api以外に、SDK付属のコマンドラインツールからログを取ってくることができます。以下ドキュメントを参照。
Downloading Logs - Uploading and Managing a Java App - Google App Engine — Google Developers
こんな感じでとってきてCloud Storageにあげます。なぜかRubyです。
--num_daysに2と指定しているのは2日分のログ、という意味です。1日分だけ欲しいのですが、timezoneを指定する手段がなく太平洋標準時間基準で取ってくることになるため、やむを得ません。あとからgrepして落とします。リクエストログが嫌でもついてくるので、これも落とします。（IPやUAが入ってセンシティブで扱いにくいのです）
はい、というわけでなんの面白みもないですが、SDKでごそっと持ってくる方法に落ち着きました。そしてこっからの集計は現状全部シェルでやっています。世の中にはBigQueryを使うという手もあるようですが（参考：02.macheでApp EngineのログをBigQueryにコピーして解析｜CA Beat エンジニアのブログ）、awkと違ってBigQueryは実行単位で課金されます。（ひいぃ！）
いまのとここれでうまくいっています。とはいえ、リアルタイムに見たいデータもあって、dailyのレポーティング用途とは別に、レコメンドの集計のために数時間単位でログを取りに行っていたり、Cloud SQLのレイテンシを監視するために（以下同文）してたりします。このへんの解決のために外部のfluentdにHTTPSでpostする処理を書いたのですが、それはまた今度書きます。
GAEのようなPaaSは気軽に使い始めることができて、柔軟にスケールすることができるってことでスタートアップに向いていると言われます。が、ログの記録や集計ごときに手間取らせるようではとてもスタートアップに向いているとは思えません。App Engineに片足突っ込んでしまった身としては、このあたりの機能拡充を望みたいところです。
