OpenTelemetry で始める分散トレース

昨今、オブザーバビリティという言葉を耳にすることが増えました。オブザーバビリティとは、システムの状態をどれだけ理解し説明できるかを示す尺度です。

近年のソフトウェアは分散システムに始まり複雑化しているため、挙動を把握するための情報を集めて分析することで、システムを理解できるようにすることが重要です。このような情報にはメトリクス・トレース・ログがあり、[OpenTelemetry](https://opentelemetry.io/) はこれらを取得するためのOSSツールです。

この記事では、OpenTelemetry を使ってトレースを取得しようとしている方向けに、色々なケースで取得する方法を紹介します。

# 前提
言語：Golang 1.20.3
実行環境：GCP Cloud Run

# 分散トレースの重要性
分散トレース（単にトレースとも呼ばれます）とは、1つのリクエストがアプリケーションを構成するさまざまなサービスによって処理される過程を追跡する方法です。<br>
処理過程のどこで障害が発生しているか、パフォーマスが低下しているかという原因を特定するのに有効です。<br>
トレースを模式図で表現すると以下のようになります。

<img width="484" alt="スクリーンショット 2023-08-16 9.08.17.png (52.0 kB)" src="https://img.esa.io/uploads/production/attachments/17300/2023/08/16/63938/f61fb3fe-2857-4883-a96c-462d03384d58.png">

- 赤枠：HTTPリクエスト `/api/get/all-resource` を受信しレスポンスを返すまでの期間
- 青枠：サービスAを呼び出して結果を返すまでの期間
- 緑枠：サービスAがデータを取得するまでの期間

このように処理過程が視覚化されると、「サービスAがデータを取得する」部分がボトルネックになっていることが分かります。

# トレースの構成要素
トレースはスパンによって構成され、特にトレース内の最上位にあるものはルートスパンと呼ばれます。入れ子になっているスパンには親子関係があり、赤枠の子スパンが青枠であり、青枠の子スパンが緑枠という関係になっています。

<img width="823" alt="スクリーンショット 2023-08-16 9.08.34.png (145.9 kB)" src="https://img.esa.io/uploads/production/attachments/17300/2023/08/16/63938/bd269bf1-9bf0-4b0c-bc88-9255f3dca605.png">

このような視覚化を行なうために各スパンは以下の情報を保持しています。

- トレースID：トレースを一意に識別するもの。同じトレースIDを持つスパンが同一のトレースに含まれる。
- スパンID：スパンを識別するもの。
- 親ID：親スパンのスパンID。ルートスパンは親IDを持たない。
- タイムスタンプ：スパンが開始された日時。
- 継続時間：スパンが終了するまでにかかった時間。

それでは次に、トレースに必要なこれらの情報をアプリケーションで取得する方法を見ていきます。

# OpenTelemetry のセットアップ
まずはトレースデータを取得するために、OpenTelemetryのセットアップを記述します。

```go
import (
	"cloud.google.com/go/compute/metadata"
	"context"
	cloudtrace "github.com/GoogleCloudPlatform/opentelemetry-operations-go/exporter/trace"
	"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
	"go.opentelemetry.io/otel"
	"go.opentelemetry.io/otel/propagation"
	sdkTrace "go.opentelemetry.io/otel/sdk/trace"
	"log"
	"net/http"
	"time"
)

func initTracer() error {
	meta := metadata.NewClient(nil)
	projectId, err := meta.ProjectID()
	if err != nil {
		log.Fatalf("failed to find project ID: %v", err)
	}
	exporter, err := cloudtrace.New(cloudtrace.WithProjectID(projectId))
	if err != nil {
		return err
	}
	tp := sdkTrace.NewTracerProvider(
		sdkTrace.WithBatcher(exporter),
		sdkTrace.WithSampler(sdkTrace.AlwaysSample()),
	)
	otel.SetTracerProvider(tp)
	otel.SetTextMapPropagator(propagation.TraceContext{})
	return nil
}
```

ここで設定している [TracerProvider](https://opentelemetry.io/docs/specs/otel/trace/api/#tracerprovider) とは Tracer にアクセスするための窓口であり、Tracer はスパンを生成します。スパンを生成したい箇所で TracerProvider から Tracer を取得しスパンを生成します。<br>
OpenTelemetry で収集したデータを視覚化するには、Jaeger, GCP Cloud Trace のようなベンダー固有のものにデータをエクスポートする必要があり、ここでは Cloud Trace で視覚化するための Exporter を設定しています。

セットアップが完了したら、スパンを生成する方法をケース毎に見ていきます。

# incoming request
HTTPリクエストを受信しレスポンスを返す処理において、手動でスパンを開始・終了することもできますが、Go では otelhttp パッケージの [NewHandler](https://pkg.go.dev/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp#NewHandler) を使って自動で生成することができます。
第一引数に `http.Handler`、第二引数に生成されるスパンの名前を渡します。

```go
func main() {
	err := initTracer()
	if err != nil {
		log.Fatal(err)
	}
	otelHandler := otelhttp.NewHandler(http.HandlerFunc(helloHandler), "helloHandler")
	http.Handle("/hello", otelHandler)
	http.ListenAndServe(":8080", nil)
}

func helloHandler(writer http.ResponseWriter, request *http.Request) {
	time.Sleep(time.Second * 3)
}
```

上記コードをCloud Run にデプロイした後、APIエンドポイント `/hello` にアクセスし Cloud Trace を見ると、次のように3つのスパンを確認することができます（スパンが4つに見えますが、最上位のものはトレース全体を表現しているものでスパンではありません）。

<img width="892" alt="スクリーンショット 2023-08-14 17.10.55.png (96.2 kB)" src="https://img.esa.io/uploads/production/attachments/17300/2023/08/14/63938/e9f5ce13-261f-48be-8fcb-6a0cacd423d6.png">

`helloHandler` というスパンが先ほどのコードで生成したものです。一方、`hello` という名前の2つのスパンは上記のコードとは関係なく、Cloud Run によって自動生成されたものです。

Cloud Run が自動生成したスパンのスパンIDやトレースIDは HTTPリクエストヘッダーに含まれており、`otelhttp.NewHandler` が生成した otelhttp のハンドラはヘッダーからそれらの情報を抽出して`helloHandler`スパンを生成することで、スパンの親子関係を紐づけています。

# outgoing request
今度はHTTPリクエストを発行する側でスパンを生成してみます。
otelhttp パッケージの [NewTransport](https://pkg.go.dev/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp#NewTransport) を使って `http.Client` を組み立ててリクエストを発行することで、こちらも自動でスパンを生成します。

先ほどの `helloHandler` に `http://httpbin.org/get` へGETリクエストを投げる関数を次のように追加します（[httpbin.org](https://httpbin.org/) はHTTPリクエストとレスポンスを返してくれるサービスです）。

```go
func helloHandler(writer http.ResponseWriter, request *http.Request) {
	time.Sleep(time.Second * 3)
	callAnotherService(request.Context())
}

func callAnotherService(ctx context.Context) {
	request, err := http.NewRequestWithContext(ctx, "GET", "http://httpbin.org/get", nil)
	if err != nil {
		log.Fatal(err)
	}
	client := http.Client{
		Transport: otelhttp.NewTransport(http.DefaultTransport),
	}
	resp, err := client.Do(request)
	if err != nil {
		log.Fatal(err)
	}
	// span ends after resp.Body.Close.
	resp.Body.Close()
}
```

<img width="1096" alt="スクリーンショット 2023-08-14 19.09.58.png (110.1 kB)" src="https://img.esa.io/uploads/production/attachments/17300/2023/08/14/63938/30eec5e2-99f2-4507-acbd-9d3a27eb20e7.png">

`helloHandler` スパンを開始して約3秒後に`HTTP GET`スパンが開始され、その期間を見ると`http://httpbin.org/get` からレスポンスを受信するまでに約3.8秒かかったと考えられます。

# 手動でスパンを生成する
上述のように incoming/outgoing リクエストでスパンを自動生成できるため、トレースのためにコードを追加する労力を抑えることができます。<br>
通信を伴わない内部処理を手動でトレースしたい場合は、次のようにしてスパンを生成することができます。


先ほどの `helloHandler` で内部関数を呼び出すように変更します。関数の最初で Tarcer を取得してスパンを生成し、関数の実行が終わったらスパンを終了します。

```go
func helloHandler(writer http.ResponseWriter, request *http.Request) {
	time.Sleep(time.Second * 3)
	callInternalMethod(request.Context())
}

func callInternalMethod(ctx context.Context) {
	_, span := otel.Tracer("otelHttpTracer").Start(ctx, "internalMethod")
	defer span.End()
	time.Sleep(time.Second * 1)
}
```

<img width="1169" alt="スクリーンショット 2023-08-14 19.31.45.png (143.7 kB)" src="https://img.esa.io/uploads/production/attachments/17300/2023/08/14/63938/2c308e92-71dd-4ddb-a201-59c673de8252.png">

そうすると、`helloHandler` の子スパンに `internalMethod` スパンを生成できました。

# システム連携
これまでは単一システムでのトレースでしたが、次は2つのシステムが連携する処理をトレースしてみます。
Cloud Run サービスを2つ用意して、以下のようにサービスAがサービスBを呼び出す構成を作ります。

<img width="522" alt="スクリーンショット 2023-08-15 11.58.36.png (34.5 kB)" src="https://img.esa.io/uploads/production/attachments/17300/2023/08/15/63938/20e366dc-7a4e-4cdb-8a38-35ea1064b3b5.png">

### サービスAの実装
サービスAは「outgoing request」の実装とほぼ同じで、リクエスト先をサービスBのエンドポイント `https://cloud-run-service-b-sample/hello2` に変更します。
これでサービスAの `/hello` が叩かれると サービスBの `/hello2` が呼び出されます。

```go
func main() {
	err := initTracer()
	if err != nil {
		log.Fatal(err)
	}
	otelHandler := otelhttp.NewHandler(http.HandlerFunc(helloHandler), "helloHandler")
	http.Handle("/hello", otelHandler)
	http.ListenAndServe(":8080", nil)
}

func helloHandler(writer http.ResponseWriter, request *http.Request) {
	callAnotherService(request.Context())
}

func callAnotherService(ctx context.Context) {
	request, err := http.NewRequestWithContext(ctx, "GET", "https://cloud-run-service-b-sample/hello2", nil)
	if err != nil {
		log.Fatal(err)
	}
	client := http.Client{
		Transport: otelhttp.NewTransport(http.DefaultTransport),
	}
	resp, err := client.Do(request)
	if err != nil {
		log.Fatal(err)
	}
	// span ends after resp.Body.Close.
	resp.Body.Close()
}
```

ポイントになるのが [otelhttp.NewTransport](https://github.com/open-telemetry/opentelemetry-go-contrib/blob/v1.17.0/instrumentation/net/http/otelhttp/transport.go#L114) で、この処理でHTTPリクエストヘッダーにトレースID・スパンIDをセットしています。
これは、サービスAで生成したスパンとサービスBで生成したスパンを関連付けて、トレースを組み立てられるようにするためです（[Context Propagation](https://opentelemetry.io/docs/concepts/signals/traces/#context-propagation) と呼ばれる概念）。
サービスBではリクエストヘッダからトレースID・スパンIDを抽出してスパンの生成に使用します。

### サービスBの実装

サービスBは `/hello2` エンドポイントを用意し、2秒間sleepした後にレスポンスを返す `hello2Handler` を実装します。実装は「incoming request」とほぼ同じです。

```go
func main() {
	err := initTracer()
	if err != nil {
		log.Fatal(err)
	}
	otelHandler2 := otelhttp.NewHandler(http.HandlerFunc(hello2Handler), "hello2Handler")
	http.Handle("/hello2", otelHandler2)
	http.ListenAndServe(":8080", nil)
}

func hello2Handler(writer http.ResponseWriter, request *http.Request) {
	time.Sleep(time.Second * 2)
}
```

`otelhttp.NewHandler` でリクエストヘッダーに含まれるトレースID・スパンIDを抽出し、新しく生成するスパンに情報をセットしています。

サービスA・サービスBをCloud Run にデプロイし、サービスAの `/hello` を叩くと以下のトレースを確認できます。

<img width="1321" alt="スクリーンショット 2023-08-15 16.43.03.png (141.7 kB)" src="https://img.esa.io/uploads/production/attachments/17300/2023/08/15/63938/435df025-0783-4aa5-94f4-dc409af573f6.png">

`HTTP GET` スパンがサービスBの呼び出し元で、その子スパンとしてサービスBの `/hello2`スパンがあり、その子スパンに `hello2Handler` スパンができており、サービスAとBで同一トレースとして表示できていますね。

これでリクエスト先の処理の内訳までトレースできるようになったので、システムを横断的に見て、どこでどれだけ時間がかかっているかを理解し易くなりました。

# 非同期処理
HTTPリクエストではトレース情報を伝播するのにHTTPヘッダーを使いましたが、Cloud Pub/Sub のような非同期処理ではそれが使えません。代わりに、メッセージの属性にトレース情報を含めることで伝播することができます。
Cloud Pub/Sub を使って以下の構成を作って試してみます。

<img width="693" alt="スクリーンショット 2023-08-15 18.34.00.png (42.6 kB)" src="https://img.esa.io/uploads/production/attachments/17300/2023/08/15/63938/cdf47031-d4be-462d-9d86-6a96e5afee40.png">

サービスAの`/hello`にアクセスするとPub/Sub トピックにメッセージを送り、push サブスクリプションを使って非同期的にサービスBの `/hello2` を実行します。

### サービスAの実装
```go
func helloHandler(writer http.ResponseWriter, request *http.Request) {
	meta := metadata.NewClient(nil)
	projectId, err := meta.ProjectID()
	if err != nil {
		log.Fatalf("failed to find project ID: %v", err)
	}
	client, err := pubsub.NewClient(request.Context(), projectId)
	if err != nil {
		log.Fatalf("failed to create Pub/Sub client: %v", err)
	}
	defer client.Close()

	topic := client.Topic("sample")
	message := pubsub.Message{Data: []byte("payload sample")}
	message.Attributes = make(map[string]string)
	// トレース情報をmessage.Attributesに含める
	propagater := otel.GetTextMapPropagator()
	propagater.Inject(request.Context(), propagation.MapCarrier(message.Attributes))
	// スパンの生成
	_, span := otel.Tracer("otelHttpTracer").Start(request.Context(), "publish")
	defer span.End()

	messageId, err := topic.Publish(request.Context(), &message).Get(request.Context())
	if err != nil {
		log.Printf("failed to publish message: %v", err)
		http.Error(writer, "Bad Request: publish message", http.StatusBadRequest)
		return
	}
}
```

処理の概要としては、メッセージを組み立ててPub/Sub へ送信し、またPub/Subに送信してからレスポンスを受信するまでの間で`publish`スパンを手動生成しています。<br>
ポイントは `propagater.Inject(request.Context(),propagation.MapCarrier(message.Attributes))` です。
propagator は `propagation.TraceContext` であり、これは「OpenTelemetryのセットアップ」の`otel.SetTextMapPropagator(propagation.TraceContext{})` で設定したものです。
[propagation.TraceContext.Inject](https://github.com/open-telemetry/opentelemetry-go/blob/v1.16.0/propagation/trace_context.go#L47) で `request.Context()` に含まれるトレース情報を `message.Attributes` に詰めています。

### サービスBの実装
```go
func helloHandler2(writer http.ResponseWriter, request *http.Request) {
	body, err := io.ReadAll(request.Body)
	if err != nil {
		log.Fatalf("failed to read request body: %v", err)
	}
	type PubSubMessage struct {
		Message struct {
			Attributes map[string]string `json:"attributes"`
		} `json:"message"`
	}
	data := PubSubMessage{}
	err = json.Unmarshal(body, &data)
	if err != nil {
		log.Fatalf("failed to json.Unmarshal: %v", err)
	}
	propagator := otel.GetTextMapPropagator()
	// メッセージ属性に含まれるトレース情報を context にセットする
	ctx := propagator.Extract(request.Context(), propagation.MapCarrier(data.Message.Attributes))
	// 情報をセットした context を使ってトレースを生成する
	ctx, span := otel.Tracer("otelHttpTracer").Start(ctx, "subscribe")
	defer span.End()

	time.Sleep(time.Second * 1)
}
```
サービスAから送信されたメッセージをリクエストボディから取り出し、その中のトレース情報を抽出し、それを使って`subscribe`スパンを手動生成しています。
こちら側のポイントは `propagater.Extract(request.Context(),propagation.MapCarrier(data.Message.Attributes))`  です。
propagater は先ほどと同様に `propagation.TraceContext` で、[propagation.TraceContext.Extract](https://github.com/open-telemetry/opentelemetry-go/blob/v1.16.0/propagation/trace_context.go#L73) でメッセージ属性に含まれるトレース情報を `context.Context` にセットし、その context を使ってスパンを生成しています。

サービスA・BをCloud Run にデプロイし、サービスAの /hello を叩くと以下のトレースを確認できます。

<img width="1321" alt="スクリーンショット 2023-08-16 17.03.09.png (167.6 kB)" src="https://img.esa.io/uploads/production/attachments/17300/2023/08/16/63938/a27c003b-6992-4aaf-8e34-beda8051b8ca.png">

`publish`スパンの後にレイテンシが約3秒間あり空白として表現されています。その後、サービスBの`subscribe`スパンが生成されていることが分かりますね。

これで非同期処理でも、スパンが生成された場所に関係なくトレースを組み立てることができるようになりました。