GoでOpenTracingをやろう

はじめに

こんにちは。 アドベントカレンダー ８日目担当、 サーバーサイドエンジニアの miyauchi です。

昨年は「 Goとクリーンアーキテクチャとトランザクションと」と「Vim初心者から中級者の入り口くらいまで」を書きました。 早いものでもう一年経つのですね。

さて、弊社ではバックエンドシステムを従来のモノリス型のサービスから、徐々にマイクロサービスへ移行中です。 そんな中で分散トレーシング（とりわけOpenTracing）について調査する機会がありました。

よって、今年はGoのアプリケーションで、OpenTracingを使うときのコード集を、解説ありで書いていきたいと思います。 「OpenTracingとは！」や、「分散トレーシングとは！」のような概念部分は書きません。 また、OpenTracingのTracer実装であるjaegerについても詳細は書きません。

OpenTracingを使ったサンプルコード中心で、 チュートリアルに毛が生えたくらいの入門記事となります。

OpenTracingの具体的な使い方については、案外まとまった記事がないのかなと思ったので書こうと思ったわけですが、 一方で、少し今更感もあります、、、が、張り切っていきましょう！

分散トレーシングについて

「概念部分は書かない！」とは言ったものの、いきなりコードはやっぱりしんどいかもしれません。 なので、分散トレーシングとOpenTracingについて少しだけ説明します。

サービスを細かく分割していくと、 一回のリクエスト（HTTPリクエストなど）で複数のサービスやミドルウェアをコールすることになります。 そうすると困ってくることの一つが、一つの処理を追跡することが難しくなることが挙げられます。 例えば

「このリクエストすごく重いんだけど、いっぱいサービスコールしていてどこがボトルネックなのかわからない！」

といったものですね。

分散トレーシングは分散システムにおいてのサービス間呼び出しの追跡を助けます。

そして、OpenTracingは分散トレーシングのための、仕様、ライブラリ、ドキュメントなどから構成される開発キットのようなものです。

詳細は公式Webサイトより。 https://opentracing.io/

それでは、早速ですがコードを見ていきます。 今回紹介するソースコードは全て aptpodのGithubリポジトリ にあります。 手元でコードを見たい方はクローンをしておきましょう。

以降、コマンドなどの実行は全て、同リポジトリルートがカレントディレクトリである前提で進めます。

ミニマムアプリケーションを実装する

実装アプリケーションについて

最初にクライアントからHTTPコールするだけの、すごく簡単なミニマムアプリケーションを実装していきます。 こんな感じです。

    +--------+         
    | client |
    +---+----+
         |
^        |
| client |
| side   |
+--------+---------
| server |
| side   |
v        |
         v
    +--------------+
    | hoge-service |
    +---+----------+

はい、簡単ですね。

OpenTracingの実装の流れ

流れの説明をする前に、 OpenTracingのAPIを使っていると、Tracer、Span、SpanContextという用語が頻出します。これらについて少しだけ補足します。 要所で簡単に解説はしますが、ちゃんと理解するために The OpenTracing Data Model 、 及び The OpenTracing API を読むことをおすすめします。

ここでは、SpanとTracerについてだけ簡単に図と合わせて説明します。

 -----------------------------------------------------> time

   | parentspan                                   |
   +----------------------------------------------+
      | child span |    | child span            |
      +------------+    +-----------------------+
                           | grand child span |
                           +------------------+

• 任意の時間に特定の期間であるSpan
• Spanは入れ子にすることができる
• 一番最初にSpanを開始するのがTracer

概念だけふんわりイメージできればOKです。 繰り返しになりますが、正確な理解は本家ドキュメントを読むことをおすすめします。

では実際の実装の流れについて説明します。

OpenTracingを使うときは基本的には次のような流れになります。

1. Tracerの初期化（原則アプリケーション起動時に一回）
2. Tracerの取得
3. Spanの開始
   1. 親のSpanから新しいSpanの開始
      1. 親のSpanから新しいSpanの開始
      2. Spanの終了
      3. ...(任意のSpanの開始と終了)
   2. Spanの終了
   3. ...(任意のSpanの開始と終了)
4. Spanの終了

TracerからSpanを開始して、SpanからSpanを入れ子にしていくイメージです。

実装する

Tracerを初期化する

SpanはTracerが開始します。 まずはアプリケーションのどこからでも参照できる、GlobalTracerにTracerをセットしましょう。 Tracerはインターフェースとなっていて実装は様々です。 今回は、jaegerを使うので こちら のコードを参考にして、Tracerを初期化します。

jaeger独自の設定部分の解説は割愛します。 詳細は公式やGithubのリポジトリを参照してください。

下記のコードのいずれかをコールすると jaeger版のTracerの初期化が完了し、GlobalTracerにセットされます。

// ./lib/tracer.go

package lib

import (
    "io"

    "github.com/opentracing/opentracing-go"
    "github.com/uber/jaeger-client-go"
    "github.com/uber/jaeger-client-go/config"
    "github.com/uber/jaeger-client-go/log"
    "github.com/uber/jaeger-lib/metrics"
)

func InitGlobalTracer(serviceName string) (io.Closer, error) {

    return initGlobalTracer(config.Configuration{
        Sampler: &config.SamplerConfig{
            Type:  jaeger.SamplerTypeConst,
            Param: 1,
        },
        Reporter: &config.ReporterConfig{
            LogSpans: true,
        },
    }, serviceName)
}

func InitGlobalTracerProduction(serviceName string) (io.Closer, error) {
    return initGlobalTracer(config.Configuration{}, serviceName)
}

func initGlobalTracer(cfg config.Configuration, serviceName string) (io.Closer, error) {
    jLogger := log.StdLogger
    jMetricsFactory := metrics.NullFactory
    return cfg.InitGlobalTracer(
        serviceName,
        config.Logger(jLogger),
        config.Metrics(jMetricsFactory),
    )
}

GlobalTracerにセットするコードを紹介しましたが、そうではなく、オブジェクトとして生成し使い回すことも可能です。

// ./lib/tracer.go

func CreateTracer(serviceName string) (opentracing.Tracer, io.Closer, error) {
    var cfg config.Configuration
    jLogger := log.StdLogger
    jMetricsFactory := metrics.NullFactory
    cfg.ServiceName = serviceName
    return cfg.NewTracer(
        config.Logger(jLogger),
        config.Metrics(jMetricsFactory),
    )
}

クライアントを実装する

次にクライアント側の実装コードを見ていきます。

// ./minclient/main.go
package main

import (
    "errors"
    "io/ioutil"
    "log"
    "net/http"

    "github.com/aptpod/opentracing-sandbox/lib"
    "github.com/opentracing/opentracing-go"
)

func main() {
    // Tracerの初期化
    closer, err := lib.InitGlobalTracer("client")
    if err != nil {
        panic(err)
    }
    defer closer.Close()

    // Tracerの取得
    tracer := opentracing.GlobalTracer()

    // Spanの開始
    // このSpanを引き回す
    span := tracer.StartSpan("get_hoge")

    // Spanの終了
    defer span.Finish()

    // Hogeの呼び出し！
    res, err := getHoge(span)
    if err != nil {
        panic(err)
    }
    log.Println(res)
}

このコード断片については難しいことはないと思います。「OpenTracingの実装の流れ」 でも述べた通り、

1. Tracerを初期化して...
2. Tracerを取得して...
3. Spanを開始して...
4. 処理(Hogeサービスの呼び出し)をして...
5. Spanを終了する。

という流れが読み取れると思います。

一点、 HTTPコールは単純にHTTPを呼び出せばよいというわけではありません。 サービス間の流れを追跡するOpenTracingですから、Spanの情報を引き継ぐ必要があります。

コード中でのHTTPコールの実装箇所はgetHoge()関数内にあたるので、 掘り下げて見ていきましょう。

// ./minclient/main.go

... omitted

func getHoge(span opentracing.Span) (string, error) {
    // リクエストの生成
    // 今回はHogeのPath
    url := "http://localhost:18080"
    req, err := http.NewRequest(http.MethodGet, url, nil)
    if err != nil {
        return "", err
    }

    // ※ Tracerを使ってSpanの情報をInject
    if err := span.Tracer().Inject(
        span.Context(),
        opentracing.HTTPHeaders,
        opentracing.HTTPHeadersCarrier(req.Header),
    ); err != nil {
        return "", err
    }

    // 通常のHTTPアクセス
    resp, err := Do(req)
    if err != nil {
        return "", err
    }

    return string(resp), nil
}

サービス間で情報を引き継ぐには、HTTPリクエストに何かしらの方法でSpanの情報を埋め込む必要があります。 引き継ぐSpanの情報（情報だと少し語弊があるかもしれませんが。。。） をSpanContextと言います。

OpenTracingではTracerがSpanContextをリクエストに埋め込む責務を追います。送信側でリクエストにSpanContextを入れることをInject、逆に受信側でSpanContextを取り出すことをExtractと言います。 また、Injectして、SpanContextを運ぶものをCareerと言います。

今回はHTTPヘッダをCareerとして、SpanContextをInjectしています。 さて、このCareerですが、HTTP以外のRPCコール時ももちろん考慮されていて、HTTPヘッダ以外にも種類があります。 気になる方はOpenTracingの実装を読んでみましょう。

// SpanContext伝播のイメージ
    +----------+
    | service1 | `Inject` `SpanContext` to `Career`
    +---+------+
         |
         | Carry using `Career`
         |
         v
    +----------+
    | service2 | `Extract` `SpanContext` from `Career`
    +---+------+

さて、Injectをしたら、あとは通常通りにHTTPコールすればOKです。 コード中ではresp, err := Do(req)の部分ですが、この部分はそのままHTTPコールしているだけなので割愛します。

hogeサービスを実装する

今度は受信側の実装です。

package main

import (
    "log"
    "net/http"
    "time"

    "github.com/aptpod/opentracing-sandbox/lib"
    "github.com/opentracing/opentracing-go"
    "github.com/opentracing/opentracing-go/ext"
)

func main() {
    // tracer の初期化
    tracer, closer, err := lib.CreateTracer("hoge-service")
    if err != nil {
        panic(err)
    }
    defer closer.Close()
    log.Println("start hoge")
    http.ListenAndServe(":18080", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        log.Println("hoge")
        // SpanのExtract
        spanCtx, _ := tracer.Extract(opentracing.HTTPHeaders, opentracing.HTTPHeadersCarrier(r.Header))

        // リクエストからのSpanContextを引き継いで新しいSpanの開始
        span := tracer.StartSpan("get_hoge", ext.RPCServerOption(spanCtx))
        defer span.Finish()
        // ダミー処理
        <-time.After(time.Second)
        w.WriteHeader(http.StatusOK)
        w.Write([]byte(`{ "name": "hoge!" }`))
    }))
}

まずはTracerの初期化部分です。 サービス側の実装はGlobalTracerへセットするのではなく、新たにTracerを生成してみます。 GlobalTracerでも良いのですが、サンプルなので。。。

１アプリケーションで複数のTracerが必要な場合はそれぞれで生成するとよいでしょう。

次はリクエストハンドラ(http.HandlerFunc)の実装です。

リクエストハンドラ内で、まず伝播されたSpanContextをExtractします。 そして、そのSpanContextを利用して、新しくSpanを開始しています。

ext.RPCServerOption(spanCtx)はSpanContextから適切なStartSpanOptionを返す関数です。 そういうものだと思って指定します。 内容が気になる方は全然難しくない実装なのでぜひ追って見てください。

さて、ここまででミニマムコードができました。

動作確認

準備

Dockerで jaeger を起動しておきます。下記に示すコマンドで、UIも含めアプリケーションが起動します。

 docker run --rm -p 6831:6831/udp -p 6832:6832/udp -p 16686:16686 jaegertracing/all-in-one:1.7 --log-level=debug

ブラウザでUIを開いておきます。アドレスは http://localhost:16686/search です。

実行

hogeサービスを起動します。

go run ./minserver/*.go

クライアントを実行します。

go run ./minclient/*.go

ブラウザを確認すると、Spanなどが確認できるかと思います。

jaegerのUI

めでたく、トレースできました。。。。。

しかしながら、Span の情報が少なかったり、実装も少し冗長だったり、まだまだ実アプリケーションへの導入は難しそうです。

以降のセクションで少しずつ洗練していきましょう。

その他の実装リファレンス

Tags/Logs/Baggage

SpanにはTag、Log、Baggageという付加情報をつけることができます。詳細は Tags, logs and baggage を参照してください。

このセクションではそれぞれの情報をどうやって付与するか、コード断片を紹介します。

SpanにTagをつける

Spanにはkey-value形式で任意のTagをつけることが可能です。

tagValue := ...
span.SetTag("tag.key", tagValue)

また、github.com/opentracing/opentracing-go/extにTagの変数があるので、適宜利用すると良いでしょう。

// Tagをつける例
ext.SpanKindRPCClient.Set(span)
ext.SpanKindRPCServer.Set(span)
ext.HTTPUrl.Set(span, "http://localhost:8080")
ext.HTTPMethod.Set(span, http.MethodGet)
ext.HTTPStatusCode.Set(span, http.StatusOK)

SpanにLogを記録する

github.com/opentracing/opentracing-go/logを使い、Span内でLogをつけます。

// Key-Value形式で簡易指定
span.LogKV(
    "hoge.log.key1", "hoge-log",
    "hoge.log.key2", "hoge-log2",
)
// 型情報ありの指定
span.LogFields(
    tracelog.String("hoge.logfields.string", "hoge-log"),
    tracelog.Bool("hoge.logfields.bool", true),
)

Logはこの関数を呼び出したタイミングで、Spanに印をつけるイメージです。

Baggageを使って情報を任意の情報を伝播する

OpenTracingには（APIのI/Fを変更せずに）任意のオブジェクトを伝播する手段があります。 運ぶ情報をBaggageと呼びます。 強力な機能ですが、使い方には注意しましょう。

• 送信(client)側

baggage := ...
span.SetBaggageItem("baggage", baggage)

• 受信(server)側

spanCtx, _ := tracer.Extract(opentracing.HTTPHeaders, opentracing.HTTPHeadersCarrier(r.Header))
span := tracer.StartSpan("format", ext.RPCServerOption(spanCtx))
defer span.Finish()
// Baggageの取得
baggage := span.BaggageItem("baggage")

context.Contextを利用する

アプリケーションをモジュール化して実装するとSpanオブジェクトを引き回すのが辛いケースがあると思います。 そこで、OpenTracingのライブラリにはcontext.Context内にSpanを含めるユーティリティが用意されています。 利用できるのであれば、コードがシンプルになるのでcontext.Context使う方が良いと思います。

• ContextにSpanをセット

span := ...
ctx := ...
ctx = opentracing.ContextWithSpan(ctx, span)

• ContextからSpanを取得

ctx := ...
span := opentracing.SpanFromContext(ctx)

• ContextにあるSpanを親として、新しくSpanを開始

ctx := ...
// もし、ctxにSpanがない場合はGlobalTracerからSpanを開始する
span := opentracing.StartSpanFromContext(ctx, "new-operation-name")

サンプルアプリケーションを実装する

これまでは、ミニマムな実装とコード断片で解説してきました。 前提となるコード知識はついてきたので、サービスの依存関係がすこしだけ複雑なアプリケーションのソースコードも見ていきます。 ソースコードを細かく解説すると長くなるので、解説はミニマムアプリケーションとの差分だけにします。

実装アプリケーションについて

まずはアプリケーションの全体像です。 矢印の番号は呼び出し順序を表しています。

    +--------+         
    | client |
    +---+----+
        1|
^        |
| client |
| side   |
+--------+-------------------------------------------------
| server |
| side   |
v        |
         v
    +--------------+ 3   +--------------+ 
    | hoge-service |---->| fuga-service |
    +---+----------+     +---+------+---+
       2|                   4|     5|          
        |                    |      +---------+
        |                    |                |
        v                    v                v
    +--------------+     +-------------+  +-------------+
    | foo-service  |     | bar-service |  | baz-service |
    +--------------+     +-------------+  +-------------+

この呼出関係をjaegerで見ることができればOKです。

サービスの実装

各サービスのHttpハンドラにTagを付けていきます。Tagについては説明したとおりです。 http.HandlerFunc実装のみの抜粋です。

// ./server/baz.go
http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
    log.Println("baz")
    // SpanのExtract
    spanCtx, _ := tracer.Extract(opentracing.HTTPHeaders, opentracing.HTTPHeadersCarrier(r.Header))

    // リクエストからのSpanContextを引き継いで新しいSpanの開始
    span := tracer.StartSpan("get_baz", ext.RPCServerOption(spanCtx))
    defer span.Finish()
    // タグ付け
    ext.HTTPMethod.Set(span, r.Method)
    ext.HTTPUrl.Set(span, r.URL.String())

    <-time.After(time.Second)
    w.WriteHeader(http.StatusOK)
    w.Write([]byte(`{ "name" : "baz!" }`))

    // タグ付け
    ext.HTTPStatusCode.Set(span, http.StatusOK)
})

ポイントは

// タグ付け
ext.HTTPMethod.Set(span, r.Method)
ext.HTTPUrl.Set(span, r.URL.String())

... omitted

// タグ付け
ext.HTTPStatusCode.Set(span, http.StatusOK)

です。全ハンドラにこのコードを実装しておけば、 UIから見たときにフィルタしやすくなります。

サービス間のAPIコールの実装

クライアントの実装と同じことをすれば良いのですが、 今回の実装はSpanをcontext.Contextに入れて伝播します。 まずは、 context.Context にセットするコードです。

// ./server/hoge.go

... omitted

// リクエストからのSpanContextを引き継いで新しいSpanの開始
span := tracer.StartSpan("get_hoge", ext.RPCServerOption(spanCtx))
defer span.Finish()

... omitted

// ctxにセット
ctx := r.Context()
ctx = opentracing.ContextWithSpan(ctx, span)

// APIコール
_, _ = cli.Call(ctx, "foo")
_, _ = cli.Call(ctx, "fuga")

あまり難しくはないですね。

次はAPIコール部分のcli.Callの実装です。 context.ContextからSpanを開始する点がポイントです。

// ./server/client.go

type ServiceClient struct {
    tracer opentracing.Tracer
}

func (s *ServiceClient) Call(ctx context.Context, serviceName string) (int, map[string]interface{}) {
    // ctxにセットされているSpanから新しく子のSpanを開始する
    span, _ := opentracing.StartSpanFromContextWithTracer(ctx, s.tracer, fmt.Sprintf("call_%s_%s", http.MethodGet, serviceName))
    defer span.Finish()
    serviceURL, _ := url.Parse(fmt.Sprintf("http://localhost:%d", portMapping[serviceName]))
    req, _ := http.NewRequest(http.MethodGet, serviceURL.String(), nil)

    // Tag付け
    ext.SpanKindRPCClient.Set(span)
    ext.HTTPUrl.Set(span, serviceURL.String())
    ext.HTTPMethod.Set(span, "GET")

    // Tracerを使ってSpanの情報をInject
    _ = span.Tracer().Inject(
        span.Context(),
        opentracing.HTTPHeaders,
        opentracing.HTTPHeadersCarrier(req.Header),
    )

    resp, _ := http.DefaultClient.Do(req)

    defer resp.Body.Close()
    var responseJson map[string]interface{}
    json.NewDecoder(resp.Body).Decode(&responseJson)
    return resp.StatusCode, responseJson
}

context.ContextからSpanを開始するのはこの部分です。

// ctxにセットされているSpanから新しく子のSpanを開始する
span, _ := opentracing.StartSpanFromContextWithTracer(ctx, s.tracer, fmt.Sprintf("call_%s_%s", http.MethodGet, serviceName))
defer span.Finish()

簡単ですね。

さて、これで準備はできました。

動作確認

Jaegerを起動した状態で サービス群を起動します。

go run ./server/*.go

クライアントを実行します。

go run ./client/*.go

そして、localhost:16686にアクセスしてみましょう。あえて、スクショははりません。ぜひ動かしてみてください！

サービス間の呼び出しがこんな感じで見ることができたらシステムの運用ちょっと楽になりそうですよね。

実装をもっと楽したい

サーバー側、クライアント側のコードを見ていただくと分かると思いますが、 まだ少し冗長です。Tagをつける部分とか。。。

go-stdlib のライブラリを使うと、 もう少し処理を共通化することができます。

リポジトリを覗いてみると、サーバー側はミドルウェアの実装、クライアント側はトランスポートの実装があるので、 適宜利用すると良いでしょう。 但し、まだ実験段階のようなので、使うときには注意しましょう。

最後に

少し長い記事となってしまいました。 OpenTracing x Go の理解の一助となれば幸いです。

ここまでくれば、もっと実践的なアプリケーションサンプル Hot R.O.D. - Rides on Demand も読み解きやすいと思います。

また、導入する際は Best Practices もあるので、 このページも必読です。

話は変わりますが、弊社では サーバーサイドエンジニアを随時募集中です！ 私達の取り組みに興味があればぜひ気軽に遊びに来てください。

以上、アドベントカレンダー８日目担当の miyauchi でした！

明日は弊社のエンベデッドチームの要、 ochiai さんです！

参考リンク集

• 記事中のコード -> https://github.com/aptpod/opentracing-go-sandbox
• OpenTracing オフィシャルサイト -> https://opentracing.io/
• OpenTracing ユーティリティライブラリ（実験段階） -> https://github.com/opentracing-contrib/go-stdlib
• jaeger オフィシャルサイト -> https://www.jaegertracing.io/
• jaeger Github -> https://github.com/jaegertracing/jaeger
• jaeger client Github -> https://github.com/jaegertracing/jaeger-client-go