スパンを手作りすることで OpenTelemetry のトレースの基礎を理解する

Mackerel では OpenTelemetry の主要なシグナルのうちのトレースに対応した分散トレーシング機能である Vaxila が使えるようになりました。Web アプリケーションのハンドラをラップすることで簡単に計装するライブラリなどは使ったことがあるのですが、今回は自分でスパンを作りトレースを計装することでより理解を深めてみようと思います。

分散トレーシングサービス Vaxila（ヴァキシラ）が Mackerel の機能として使えるようになりました - Mackerel ブログ #mackerelio
分散トレーシングサービス Vaxila(ヴァキシラ)ってどんなサービス？ - Mackerel Tech Day開催記念連載 #2 - Mackerel ブログ #mackerelio

今回は HTTP リクエストが送信されてからレスポンスが返ってくるまでの時間をトレースしてみようと思います。Mackerel の外形監視ではステータスコード、証明書の有効期限、レスポンスボディのチェックやレスポンスタイムの可視化などはできますが、DNS の名前解決、コネクションの確立、TLS ハンドシェイクの時間などを見ることができないためこれらをスパンとして送信してみます。

概念のおさらい

トレースの概念に関しては OpenTelemetry のドキュメントが簡潔にまとまっていてわかりやすいです。 - トレース | OpenTelemetry - Overview | OpenTelemetry

HTTP リクエスト内部の計装

単純に HTTP リクエストを計装するだけなら otelhttp package を使用し、既存の handler や middleware をラップするだけで完結しますが、今回は DNS の名前解決なども計装したいので otelhttp.NewTransport を用いて Transport を差し替えます。Go で DNS の名前解決などの HTTP リクエスト内部のイベントをトレースするには httptrace package が使用できます（用語が混じってややこしいですがこちらは OTel のトレースとは別物）。ClientTrace の定義を見るとわかるように、名前解決の開始と終了、TLS ハンドシェイクの開始と終了など様々なタイミングにフックを仕込むことができます。

trace package と上記のフックを組み合わせて HTTP の内部処理のスパンを作成します。tracer.Start / tracer.End にオプションを渡すことでタイムスタンプや属性など様々な設定ができます。実際にやってみたのが以下のコード。

package main

import (
    "context"
    "crypto/tls"
    "log"
    "net/http"
    "net/http/httptrace"
    "time"

    "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
    "go.opentelemetry.io/otel"
    "go.opentelemetry.io/otel/attribute"
    "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc"
    sdktrace "go.opentelemetry.io/otel/sdk/trace"
    "go.opentelemetry.io/otel/trace"
)

func initTracer() func() {
    exporter, err := otlptracegrpc.New(context.Background())
    if err != nil {
        log.Fatalf("failed to initialize exporter: %v", err)
    }

    tp := sdktrace.NewTracerProvider(sdktrace.WithBatcher(exporter))
    otel.SetTracerProvider(tp)

    return func() {
        if err := tp.Shutdown(context.Background()); err != nil {
            log.Fatalf("failed to shut down tracer provider: %v", err)
        }
    }
}

func main() {
    shutdown := initTracer()
    defer shutdown()

    url := "https://example.com"

    client := http.Client{
        Transport: otelhttp.NewTransport(
            http.DefaultTransport,
            otelhttp.WithClientTrace(func(ctx context.Context) *httptrace.ClientTrace {
                tracer := otel.Tracer("example/client")

                var dnsStart, handShakeStart, connStart time.Time
                var host string

                return &httptrace.ClientTrace{
                    DNSStart: func(info httptrace.DNSStartInfo) {
                        dnsStart = time.Now()
                        host = info.Host
                    },
                    DNSDone: func(info httptrace.DNSDoneInfo) {
                        dnsEnd := time.Now()
                        _, span := tracer.Start(ctx, "DNS Lookup",
                            trace.WithTimestamp(dnsStart),
                            trace.WithAttributes(attribute.String("host", host)),
                            trace.WithSpanKind(trace.SpanKindClient),
                        )
                        span.End(trace.WithTimestamp(dnsEnd))
                    },
                    TLSHandshakeStart: func() {
                        handShakeStart = time.Now()
                    },
                    TLSHandshakeDone: func(state tls.ConnectionState, err error) {
                        handShakeEnd := time.Now()
                        _, span := tracer.Start(ctx, "TLS Handshake",
                            trace.WithTimestamp(handShakeStart),
                            trace.WithAttributes(attribute.Int("CipherSuite", int(state.CipherSuite))),
                            trace.WithSpanKind(trace.SpanKindClient),
                        )
                        if err != nil {
                            span.RecordError(err)
                        }
                        span.End(trace.WithTimestamp(handShakeEnd))
                    },
                    ConnectStart: func(network, addr string) {
                        connStart = time.Now()
                    },
                    ConnectDone: func(network, addr string, err error) {
                        connEnd := time.Now()
                        _, span := tracer.Start(ctx, "Connection Establishment",
                            trace.WithTimestamp(connStart),
                            trace.WithAttributes(
                                attribute.String("network", network),
                                attribute.String("address", addr),
                            ),
                            trace.WithSpanKind(trace.SpanKindClient),
                        )
                        if err != nil {
                            span.RecordError(err)
                        }
                        span.End(trace.WithTimestamp(connEnd))
                    },
                }
            }),
        ),
    }

    ctx := context.Background()
    req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil)

    if err != nil {
        log.Fatalf("failed to create request: %v", err)
    }

    resp, err := client.Do(req)

    if err != nil {
        log.Fatalf("failed to perform request: %v", err)
    }

    defer resp.Body.Close()

    log.Printf("Response status: %s", resp.Status)
}

各フックポイントでタイムスタンプやホスト名、IP アドレスなどを属性として設定しています。また、エラーが起きた場合はスパンのエラーを設定しています。以下の通り HTTP リクエストを親として各内部処理がスパンとして構造化されていることがわかります。

`otelhttp.WithClientTrace` を使う

ある程度コードを書いてからドキュメントの裏どりや世の中で同じことをしている人がいないかを改めて調べてみたところ otelhttptrace というパッケージが用意されていることを知りました。¹

このパッケージを使うと http.Clientを作る部分はこれだけで済みます。

   client := http.Client{
        Transport: otelhttp.NewTransport(
            http.DefaultTransport,
            otelhttp.WithClientTrace(func(ctx context.Context) *httptrace.ClientTrace {
                return otelhttptrace.NewClientTrace(ctx)
            }),
        ),
    }

取得する情報も増えていて、より適切に構造化されていますね。

初めからこれを使えばよかったんや…という気持ちになりましたが、今回は手でスパンを作ってみるということが目的だったのでグッとその気持ちを飲み込みます。せっかくライブラリがあることを見つけたのでそちらではどういったことをしているのかを少し見てみました。

型定義を見ていくと、トレーサープロバイダーを指定したり、収集する情報のカスタマイズができるようです。デフォルトでは認証用のヘッダーが落とされるのでそれを取得するようにしたり、見つかった情報全てがスパンになることを抑制できたりもする。

clienttrace.go をのぞいてみると、フックの開始・終了処理を共通化して各タイミングで設定したい属性と一緒にそれが呼ばれています。自分で書いた実装では WithTimestamp を使って明にタイムスタンプを設定していましたが、context からスパンを取得して開始・終了のタイミングで同じスパンの Start/End を呼んでいるようです。型定義のところで見たuseSpans フラグによってイベントと属性のみ設定するという処理もありました。

Vaxila に送信してみる

最後に Vaxila にトレースを送信してみます。エクスポーターの設定を以下のように変えるだけです。標準化されたプロトコルの便利さを改めて感じますね。

   exporter, err := otlptracehttp.New(context.Background(),
        otlptracehttp.WithEndpointURL("https://otlp-vaxila.mackerelio.com"),
        otlptracehttp.WithHeaders(map[string]string{
            "Mackerel-Api-Key": os.Getenv("MACKEREL_APIKEY"),
        }),
    )

いい感じに表示されました。

実際に手を動かしてトレースを計装することにより、スパンの親子関係の設定や属性、イベントの概念のおさらいができたのと、スパンの種類や（今回の実装には出てきませんでしたが）リンクなど触れたことのない概念があるということも知ることができました。

この記事は Mackerel Advent Calendar 2024 7日目の記事でした。

qiita.com

参考にさせてもらった記事 OpenTelemetryとhttptrace.ClientTraceを使ってHTTPリクエストのlatencyを可視化する - oinume journal ↩

概念のおさらい

HTTP リクエスト内部の計装

otelhttp.WithClientTrace を使う

Vaxila に送信してみる

`otelhttp.WithClientTrace` を使う