YAMAGUCHI::weblog

海水パンツとゴーグルで、巨万の富を築きました。カリブの怪物、フリーアルバイター瞳です。

OpenCensus + Stackdriver Trace で分散トレース上にログを表示する

はじめに

こんにちは、Stackdriver担当者です。いま出張でアメリカ西海岸に来ていますが、時差ボケで破滅しています。

GCPUG Stackdriver Day January 2019でStackdriverを使った分散トレースにログを埋め込む話をしたんですが、スライドだけだともったいないと言われたのでブログの記事にもしておこうかと思います。

OpenCensusとはなにか

そもそもOpenCensusを知らないという人もまだ多いと思うので、まずそこから紹介します。OpenCensusは分散アプリケーションのメトリクスとトレースを取得するためのライブラリ群です。

opencensus.io

分散トレースのライブラリは各種APMサービスがそれぞれクライアントライブラリを出していますが、OpenCensusが特徴的なのは、TraceやStatsを取得する部分と、取得されたデータをバックエンドに送信する部分(exporter)が別れているので、バックエンドを切り替える際もexporterのインスタンスの初期化だけ書き換えれば動作するようになっていることです。また自分で独自のexporter(例: 標準出力に記録するだけのexporter)を書くこともできます。

現在 OpenCensus をサポートしているAPMツールはこちらに一覧として載っています。

opencensus.io

また今後の方向性としては OpenCensus Agent を通じてデータを送信するように変更し、これによって OpenCensus Agent 側で exporter を切り替えるだけでバックエンドが変更できるようになり、切り替えのためにソースコードを変更しなくて良くなるようにしていく予定になっています。

Stackdriver Trace

Stackdriver Trace は Google Cloud Platform が提供する APM (Application Performance Management) ツールの一つですが、特に分散アプリケーションのトレース(分散トレース)を主力機能として提供しています。Stackdriver Trace はクライアントライブラリとして OpenCensus を利用するように推奨しています。推奨しているということは当然 exporter もあります。

github.com

OpenCensusを使ってStackdriver Traceを利用する場合、Goではinstrumentationは次のようになります。

Stackdriver Trace のタイムライン内にログを埋め込む

上のサンプルのように各アプリケーション(例えばGKEクラスタで動かしている各サービス)で Trace と exporter の設定をしてからリクエストを投げてやると、次のような形で分散トレースを生成できます。

f:id:ymotongpoo:20190212082459p:plain

これでもマイクロサービス内のどこで処理時間がかかっているか簡単にわかりますが、このタイムラインの中で各Span(各サービスで行われる処理のまとまり)内で起きたイベントを確認できると便利そうです。Stackdriver Trace では Stackdriver Logging へ送信された構造化ログの中に次の2つのフィールドに適切な値が入っていた場合、そのログを Stackdriver Trace の中に表示させることができます。

  • logging.googleapis.com/trace
  • logging.googleapis.com/spanId

これら2つのフィールドに必要な Trace ID および Span ID はそれぞれHTTPヘッダやgRPCの特殊フィールドに埋め込まれていて、通常は OpenCensus のライブラリがよしなに取得できるようにしてくれています。再び Go の例で書けば次のような操作で取得できます。

func (ap *arrayParseServiceServer) Parse(ctx context.Context, pr *pb.ParseRequest) (*pb.ParsedArray, error) {
    span := trace.FromContext(ctx)
    sc := span.SpanContext()
    l := logger.WithFields(logrus.Fields{
        "logging.googleapis.com/trace": sc.TraceID.String(),
        "logging.googleapis.com/spanId":  sc.SpanID.String(),
    })
    ...
}

GKEではStackdriver Logging のエージェントが自動設定されるので、標準出力に構造化ログを出力するだけで Stackdriver Logging に送信されます。上記のフィールドに正しい値が入ったログが Stackdriver Logging に送信されると、Stackdriver Trace がそのログの中にある Trace ID と Span ID をトレースに紐づけ、タイムライン内に表示します。(タイムライン右上に [Show/Hide Logs] というボタンが表示され、ログの表示/非表示を切り替えられるようになります。)

f:id:ymotongpoo:20190212083746p:plain

またタイムライン内のログをクリックすると、画面右下に構造化ログ全体が表示されます。

f:id:ymotongpoo:20190212084113p:plain

この機能はGAEを使っていた方にはおなじみだったかもしれませんが、GKEを使っている場合においてもちょっと手を加えるだけで使えるようになるので、GKEで分散トレースを考えている場合にはぜひ利用してみてください。

参照