GAE のログに憧れて
Google App Engine (GAE) は GCP の他のサービスとの連携が豊富で非常に便利なのですが、その中でも個人的に好きな機能の一つに、Stackdriver Logging に出力されるログの見やすさがあります。
GAE のログは、上記画像のようにアクセスログとアプリケーションログを一箇所にグルーピングして表示してくれるので、両者のログを行ったり来たりする必要がありません。これは日々の開発や運用で非常に役に立ちます。
今回はこの GAE のようなログ表示に憧れて、他の GCP サービス(特に GKE)でも似たようなことを行えないか模索してみた結果をお話ししたいと思います。
TL;DR
条件付きですが、GKE でも以下のようにログをグルーピングして表示することができました。
また、これを自動で行ってくれる stackdriver-request-context-log という Go のライブラリを作りました。
Stackdriver Logging でのログのグルーピング
ログのグルーピング機能は GAE のみの機能かと思っていたのですが、Stackdriver Logging の Go ライブラリ のドキュメントに書かれてるように、いくつかの条件を満たせば GAE でなくてもグルーピングができるようです。
その条件ですが、大元のログを parent、そこにぶら下がるログを child とすると以下のようになります。
- parent, child ともに同一 GCP プロジェクトのログであること
- parent, child で log ID (logName) が別々であること
- parent, child で Monitored Resource が同一であること (つまりログが吐かれた場所が同じであること)
- parent に httpRequest.requestUrl が設定されてること (つまり parent は HTTP のアクセスログであること)
- child のログの時刻が、parent のリクエスト処理内の時刻であること (つまり child.timestamp >= parent.timestamp — parent.httpRequest.latency && child.timestamp <= parent.timestamp)
- trace が同一であること
非常に複雑ですね…。
特に3番の条件が意外と厄介で、例えば nginx のアクセスログにその配下の別のホストのアプリケーションのログをぶら下げようとしても、同一 Monitored Resource ではないため実現できません。
一方で同一ホストであれば Monitored Resource は同じになるため、アプリケーション内でアクセスログとアプリケーションログを両方書き出しているケースなどでは、うまくやればログのグルーピング化ができそうです。
GKE でのロギング
さて、では GKE (Google Kubernetes Engine) で上記の条件を満たすロギングはできるでしょうか。
GKE では Stackdriver Logging を有効にすると、標準出力と標準エラー出力に書いたログは自動で Stackdriver Logging に入るようになります。そこで、アプリケーション内でアクセスログとアプリケーションログを両方書き出すようにし、
- アプリケーションログは標準出力に書く
- アクセスログは標準エラー出力に書く
とそれぞれを使い分けると、ログのグルーピングの条件2 (logName が別々であること) も満たせるので、いけそうな気がします (本来の用途からは外れてしまいますが…)。
ただし、通常の設定では同一コンテナからのログは全て同一の logName となってしまうのですが、GKE でベータ機能として用意されている新しい Stackdriver Logging インテグレーションを使うと、標準出力と標準エラー出力を別々の logName として書き出すことができます。
設定するには GKE のクラスタを作成する際に 1.10 以上の Kubernetes のバージョンを指定する必要があります。
少し Dirty Hack 感がありますが、これで GKE でもログのグルーピング条件を満たせそうなことがわかりました！
Go 用のライブラリの作成
以上の条件に満たしたログの書き出しを自動で行ってくれる、stackdriver-request-context-log という Go のライブラリを作りました。
使い方を下記のサンプルコードを使って説明します。
ポイントは2点です。
func RequestLogging(config *Config) func(http.Handler) http.Handlerというミドルウェアにアプリケーションのhttp.Handlerを登録します。登録するとアクセスログが自動で出力されるようになります。- リクエストハンドラの中で、
func RequestContextLogger(r *http.Request) *ContextLoggerを使ってそのリクエスト内だけで有効な Logger を取得します。この Logger を使ってアプリケーションログを出力すると、自動でアクセスログと関連付けられ、Log Viewer で見た時にグルーピング化されて表示されます。
このコードを GKE のコンテナのアプリケーションとして実行すると、GAE のログのようにグルーピング化された状態でログが表示されます。
アクセスログとアプリケーションログは、実態としては別々のログとして出力されてるので、それぞれ個別に見ることも可能です。
まとめ
GAE 以外のログであっても、Stackdriver Logging でログのグルーピング化が出来ることを紹介しました。今回は GKE を例に出しましたが、GCE であっても Stackdriver Logging agent をインストールすれば同じことが出来ると思います。
皆さんも是非お使いの言語・サービスでログのグルーピングを試してみてください。
