Golang マイクロサービスの徹底トレース方法 | オブザーバビリティ基盤第3話

SRE

Golang マイクロサービスの徹底トレース方法 | オブザーバビリティ基盤第3話

こんにちは、SREグループのカンタンです！

GO株式会社ではサービス品質を向上させるためマイクロサービスのオブザーバビリティを常に改善しています。 「LGTM！オブザーバビリティ基盤第1話」という記事ではGrafanaをベースとしたオブザーバビリティ基盤を紹介し、「Grafana Lokiでログを検索 | オブザーバビリティ基盤第2話」ではログの収集と検索について話しました。

今回はサービスメッシュを活かした Golang マイクロサービスのトレース方法を紹介したいと思います。

背景

メトリックスとログの次にトレース情報がマイクロサービス開発において非常に重要なデータになっています。 複数サービスを跨いだ複雑なリクエスト処理を可視化することで、ログを見なくてもパフォーマンスのボトルネックとエラーの発生箇所など様々なインサイトを素早く発見でき、 開発と調査のスピードアップと効率化に繋がります。

GO株式会社では Grafana Stack の一つである Grafana Tempo を利用しトレース情報を収集し可視化しています。 Grafana を自前で運用しているためデータのインジェスト料金がとても安く、全てのリクエストをトレースできるようになっています！ Istio サービスメッシュを利用しているため最小限の実装で HTTP と gRPC リクエストのトレースが取れるようになっていますが、 データベースへのクエリやサービス内の関数のトレースなど、徹底的なトレースを取るにはもう少し踏み込んだ実装がまだ必要です。

全体のアーキテクチャを紹介した後、Golang サービスを徹底的にトレースするための実装方法をまとめたいと思います。 最終的に以下のようなマルチクラウドの分散トレースが取れるようになっています。

トレースサンプル

アーキテクチャ

GO株式会社では Amazon EKS と GKE を利用しマルチクラウドのマイクロサービス構成を採用しています。 Istio サービスメッシュを利用しているため各アプリケーションコンテナの前に istio-proxy (envoy) コンテナが立っていて通信をプロキシしています。 istio-proxy が通信を観察しアプリケーションへのインバウンドリクエストとアプリケーションからのアウトバウンドリクエストをトレースできるようになっています。

サービスメッシュで取れる情報はサービスメッシュで取ったほうがアプリケーションコードの変更を最小限にできとても便利ですが、Istio が対応しているのはあくまでも HTTP と gRPC リクエストのトレースだけであって、 例えば SQL データベースのクエリや内部関数のトレースを取るにはアプリケーションコードを変更しアプリケーションからトレース情報を送る必要があります。

istio-proxy とアプリケーションから出力されたトレース情報を OpenTelemetry Collector に送ることでトレース情報を加工したりフィルタしたりし最終的に Grafana Tempo に集約しています。 トレース情報を直接 Grafana Tempo に送るよりも同じ Kubernetes クラスタで動いている OpenTelemetry Collector を挟んだ方がトレース情報の送信を早めにオフロードでき、リトライやバッチ送信などのロジックをアプリケーションから切り離せます。

最終的なアーキテクチャが以下の通りになっています。

  • istio-proxy とアプリケーションがトレース情報を OpenTelemetry Collector に送る
  • OpenTelemetry Collector がトレース情報を加工しバッチで Grafana Tempo に送信
  • トレース情報がGrafana Tempo の S3 バケットに保存され、Grafana GUI から閲覧可能になっている

アーキテクチャ

トレースコンテキストの伝搬

サービスメッシュを利用しても分散トレーシングを正しく行うにはトレースコンテキストの伝搬が大事なポイントになります。 istio-proxy が全ての HTTP/gRPC リクエストをプロキシしているため、アプリケーション向けのインバウンドリクエストとアプリケーション発信のアウトバウンドリクエストを観察できます。 ただし istio-proxy からするとアプリケーション自体は完全にブラックボックスのため、インバウンドリクエストとアウトバウンドリクエストを紐づけられなくて分散トレースを正しく取得できません。

その問題を解決するため、istio-proxy がインバウンドリクエストのヘッダに追加してくれる trace ID など分散トレーシング用のコンテキストをアプリケーション側で抽出しアウトバウンドリクエストのヘッダに伝搬する必要があります。 そうすることで同じ trace ID ヘッダを持っているリクエストが同じリ処理の一部として認識され、分散トレースを正しく取得できるようになります。

また、CronJob やバックグランド処理など API リクエスト発信ではなくアプリケーション発信の処理の場合、処理の単位でトレーシング用のヘッダを生成しトレースコンテキストを初期化しアウトバウンドリクエストに伝搬する必要もあります。

トレースコンテキストの伝搬と初期化のイメージを以下の図にまとめています。

トレースコンテキスト伝搬

  • 何もしない場合はリクエストを紐付けられなくて分散トレーシングができていない
  • istio によるトレーシングヘッダ設定だけでもアプリケーションがブラックボックスのためインバウンドリクエストとアウトバウンドを紐付けられなくて分散トレーシングができていない
  • トレースコンテキストを伝搬することでin-req1とout-req1とout-req2 を紐づけられて、in-req2とout-req3を紐づけられるため分散トレーシングができている
  • 右にあるアプリケーション発信処理の場合、トレースコンテキストを初期化することで複数のアウトバウンドリクエストを紐づけられて分散トレーシングができている

実装サンプル

分散トレーシングを実現するための実装サンプルを以下にまとめています。 主に Golang での実装例になりますが参考まで Istio と OpenTelemetry Collector の設定例も追加しています。

Istio

Istio を istioctl で管理する場合以下の設定を適用することで分散トレーシングを有効にできます。

apiVersion: install.istio.io/v1alpha1
kind: IstioOperator
spec:
  meshConfig:
    # トレースIDをアクセスログに残すとログからトレースに簡単にアクセスできるため便利
    accessLogFormat: |
      {
        "start_time":"%START_TIME%",
        "protocol":"%PROTOCOL%",
        "authority":"%REQ(:AUTHORITY)%",
        "req_method":"%REQ(:METHOD)%",
        "path":"%REQ(X-ENVOY-ORIGINAL-PATH?:PATH)%",
        ...
        "trace_id":"%REQ(X-B3-TRACEID)%",
        "request_id":"%REQ(X-REQUEST-ID)%",
        ...
      }

    # トレーシングを有効にする
    enableTracing: true

    # トレース情報を Zipkin フォーマットで OpenTelemetry Collector に送れるように provider として登録する
    # Zipkin フォーマットを利用している理由は以下の OpenTelemetry Collector セクションにご参考ください
    # (OpenTelemetry Collector が monitoring ネームスペースで動いていることをイメージしている)
    extensionProviders:
    - name: opentelemetry
      zipkin:
        service: opentelemetry-collector.monitoring.svc.cluster.local
        port: 9411

    # opentelemetry provider をデフォルト provider として利用する
    defaultProviders:
      tracing:
      - opentelemetry

メッシュ全体のトレースサンプリングを 100% にする場合

apiVersion: telemetry.istio.io/v1alpha1
kind: Telemetry
metadata:
  name: mesh-default
  namespace: istio-system
spec:
  tracing:
  - randomSamplingPercentage: 100.00

OpenTelemetry Collector

GO株式会社では Helm を使ってインフラ関連のツールをインストールすることが多いです。 OpenTelemetry Collector の正式 Helm Chart を利用する場合、以下のように設定できます。

opentelemetry-collector:
  config:
    service:
      pipelines:
        traces:
          receivers:
            - zipkin # istio-proxy からのトレースを受け取るため
            - otlp # アプリケーションからのトレースを受け取るため
          processors:
            - attributes/filter
            - span/rename
            - memory_limiter
            - batch
          exporters:
            - otlphttp # Grafana Tempo に送信するため

    processors:
      attributes/filter:
        actions:
          # Extract pod name for increased readability
          - key: node_id
            pattern: ^sidecar~.+~(?P<pod>.+)\..+~.+$
            action: extract
          - key: node_id
            action: delete

          # Prepare attributes for better span name: extract base_url and path from http.url
          # example of mesh internal url: app-main:8080/path
          # example of mesh external url: example.com/path
          - key: http.url
            pattern: ^.+\/\/(?P<base_url>[^\/]+)(?P<path>\/.+)$
            action: extract
          # set ext_url to be 'example.com' in case of external url, and '' in case of internal url
          - key: ext_url
            value: ""
            action: insert
          - key: http.url
            pattern: ^.+\/\/(?P<ext_url>[^\/:]+)\/.+$
            action: extract
          # remove obsolete attributes (use base_url and path instead)
          - key: http.url
            action: delete
          - key: grpc.path
            action: delete
      span/rename:
        name:
          from_attributes: ["ext_url", "path"] #  keys used to generate the new span name
          separator: "" # string used to concatenate various parts of the span name

    exporters:
      otlphttp:
        endpoint: "https://my-grafana-tempo-endpoint.example.com/otlp"
        headers:
            Authorization: Basic xxx
  • トレース情報を受け取るために2つの receivers を設定する
    • zipkin (9411ポート) : istio-proxyから Zipkin フォーマットのトレース情報を受け取るため
    • otlp (4317ポート) : アプリケーションから OpenTelemetry Protocol フォーマットのトレース情報を gRPC で受け取るため
  • トレース情報を見やすくするため加工する（あくまでも一例だけで、ユースケースに応じて調整すると良い)
  • トレース情報を OpenTelemetry Protocol フォーマットで HTTP で Grafana Tempo に送信する

istio-proxy からのトレース情報を Zipkin フォーマットで受け取っている理由は設定した当時に Istio が Zipkin しか対応していなかったためですが最近は OpenTelemetry Protocol も対応しているようで、新規設定する方は OpenTelemetry Protocol を使うことがおすすめです。

Golang でのトレースコンテキスト伝搬

トレースコンテキストの伝搬を行うには以下の流れになります。

  • トレース ID など分散トレーシング用の情報をリクエストヘッダから抽出し Golang の ctx に入れる
  • アウトバウンドリクエストの際に ctx から分散トレーシング用の情報を取得しヘッダに追加する

例えば以下のような tracectx パッケージを用意できます。

  • AddToContext() : トレーシング情報を ctx に追加する
  • GetFromContext() : トレーシング情報を ctx から取得する
package tracectx

import "context"

type Header string

const (
    HeaderRequestID      Header = "x-request-id"
    HeaderB3TraceID      Header = "x-b3-traceid"
    HeaderB3SpanID       Header = "x-b3-spanid"
    HeaderB3ParentSpanID Header = "x-b3-parentspanid"
    HeaderB3Sampled      Header = "x-b3-sampled"
    HeaderB3Flags        Header = "x-b3-flags"
    HeaderOTSpanContext  Header = "x-ot-span-context"
)

type Tracing struct {
    RequestID      string
    B3TraceID      string
    B3SpanID       string
    B3ParentSpanID string
    B3Sampled      string
    B3Flags        string
    OTSpanContext  string
}

type dedicatedKey string

const contextKey dedicatedKey = "tracing_context"

func AddToContext(ctx context.Context, tracing Tracing) context.Context {
    return context.WithValue(ctx, contextKey, tracing)
}

func GetFromContext(ctx context.Context) Tracing {
    if value, ok := ctx.Value(contextKey).(Tracing); ok {
        return value
    }

    return Tracing{}
}

例：トレーシング情報をインバウンドリクエストのメタデータ（ヘッダ）から抽出し ctx に入れるための gRPC インターセプター

func UnaryServerInterceptor() grpc.UnaryServerInterceptor {
    return func(
        ctx context.Context,
        req interface{},
        info *grpc.UnaryServerInfo,
        handler grpc.UnaryHandler,
    ) (interface{}, error) {
        // Retrieve tracing info from grpc request metadata
        inmd := metautils.ExtractIncoming(ctx)

        tracing := tracectx.Tracing{
            RequestID:      inmd.Get(string(tracectx.HeaderRequestID)),
            B3TraceID:      inmd.Get(string(tracectx.HeaderB3TraceID)),
            B3SpanID:       inmd.Get(string(tracectx.HeaderB3SpanID)),
            B3ParentSpanID: inmd.Get(string(tracectx.HeaderB3ParentSpanID)),
            B3Sampled:      inmd.Get(string(tracectx.HeaderB3Sampled)),
            B3Flags:        inmd.Get(string(tracectx.HeaderB3Flags)),
            OTSpanContext:  inmd.Get(string(tracectx.HeaderOTSpanContext)),
        }

        // Add tracing info to context
        ctx = tracectx.AddToContext(ctx, tracing)

        // Process
        return handler(ctx, req)
    }
}

例：トレーシング情報を ctx から取得しアウトバウンドリクエストのメタデータ（ヘッダ）に追加する gRPC インターセプター

func UnaryClientInterceptor() grpc.UnaryClientInterceptor {
    return func(
        ctx context.Context,
        fullMethod string, req, reply interface{},
        cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption,
    ) error {
        // Get tracing info from context
        tracing := tracectx.GetFromContext(ctx)

        // Add tracing info to grpc request metadata
        pairs := []string{
            string(tracectx.HeaderRequestID), tracing.RequestID,
            string(tracectx.HeaderB3TraceID), tracing.B3TraceID,
            string(tracectx.HeaderB3SpanID), tracing.B3SpanID,
            string(tracectx.HeaderB3ParentSpanID), tracing.B3ParentSpanID,
            string(tracectx.HeaderB3Sampled), tracing.B3Sampled,
            string(tracectx.HeaderB3Flags), tracing.B3Flags,
            string(tracectx.HeaderOTSpanContext), tracing.OTSpanContext,
        }
        ctx = metadata.AppendToOutgoingContext(ctx, pairs...)

        // Process
        return invoker(ctx, fullMethod, req, reply, cc, opts...)
    }
}

HTTP/gRPC リクエスト以外のトレースを正しくできるように、以下のようにトレースのルートスパンを初期化する必要もあります。

import (
    // ...
    "github.com/grpc-ecosystem/go-grpc-middleware/util/metautils"
    "go.opentelemetry.io/otel"
    "go.opentelemetry.io/otel/attribute"
    semconv "go.opentelemetry.io/otel/semconv/v1.24.0"
    "go.opentelemetry.io/otel/trace"
)

func UnaryServerInterceptor() grpc.UnaryServerInterceptor {
    tracer := otel.Tracer("my-tracer")

    return func(
        ctx context.Context,
        req interface{},
        info *grpc.UnaryServerInfo,
        handler grpc.UnaryHandler,
    ) (interface{}, error) {
        // Retrieve tracing info from grpc request metadata
        inmd := metautils.ExtractIncoming(ctx)

        tracing := tracectx.Tracing{
            RequestID:      inmd.Get(string(tracectx.HeaderRequestID)),
            B3TraceID:      inmd.Get(string(tracectx.HeaderB3TraceID)),
            B3SpanID:       inmd.Get(string(tracectx.HeaderB3SpanID)),
            B3ParentSpanID: inmd.Get(string(tracectx.HeaderB3ParentSpanID)),
            B3Sampled:      inmd.Get(string(tracectx.HeaderB3Sampled)),
            B3Flags:        inmd.Get(string(tracectx.HeaderB3Flags)),
            OTSpanContext:  inmd.Get(string(tracectx.HeaderOTSpanContext)),
        }

        // Add tracing info to context
        ctx = tracectx.AddToContext(ctx, tracing)

        // Setup trace root span
        ctx, span := createTraceSpan(ctx, tracer, tracing, info.FullMethod)
        defer span.End()

        // Process
        return handler(ctx, req)
    }
}

func createTraceSpan(
    ctx context.Context, tracer trace.Tracer,
    tracing tracectx.Tracing, fullMethod string,
) (context.Context, trace.Span) {
    // setup trace context
    ctx = setupTraceSpanContext(ctx, tracing)

    // Extract request info
    service := path.Dir(fullMethod)[1:]
    method := path.Base(fullMethod)

    // create span
    attrs := []attribute.KeyValue{
        semconv.RPCSystemGRPC,
        semconv.RPCService(service),
        semconv.RPCMethod(method),
    }

    return tracer.Start(
        ctx,
        fullMethod,
        trace.WithSpanKind(trace.SpanKindServer),
        trace.WithAttributes(attrs...),
    )
}

func setupTraceSpanContext(ctx context.Context, tracing tracectx.Tracing) context.Context {
    var err error

    scc := trace.SpanContextConfig{}

    scc.TraceID, err = trace.TraceIDFromHex(tracing.B3TraceID)
    if err != nil {
        return ctx
    }

    scc.SpanID, err = trace.SpanIDFromHex(tracing.B3SpanID)
    if err != nil {
        return ctx
    }

    return trace.ContextWithRemoteSpanContext(ctx, trace.NewSpanContext(scc))
}

Golang からのトレース情報送信

上述の通りデータベースへのクエリなど Istio だけで取れなくてアプリケーションから送らないといけないトレース情報があります。 トレース情報を OpenTelemetry Collector に送るには以下のような実装ができます。

package main

import (
    "context"
    "go.opentelemetry.io/otel"
    "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc"
    "go.opentelemetry.io/otel/propagation"
    sdktrace "go.opentelemetry.io/otel/sdk/trace"
    "google.golang.org/grpc"
    "google.golang.org/grpc/credentials/insecure"
)

func main() {
    ctx := context.Background()

    // setup trace exporter
    shutdown := setupTraceExporter(ctx)
    defer shutdown(ctx)

    // start http/grpc server, execute job etc.
    // ...
}

func setupTraceExporter(ctx context.Context) func(context.Context) error {
    // setup grpc connection to opentelemetry-collector
    address := "opentelemetry-collector.monitoring.svc.cluster.local:4317"

    conn, err := grpc.DialContext(ctx, address,
        grpc.WithTransportCredentials(insecure.NewCredentials()),
        grpc.WithBlock(),
    )
    if err != nil {
        panic(err)
    }

    // create trace exporter
    traceExporter, err := otlptracegrpc.New(ctx, otlptracegrpc.WithGRPCConn(conn))
    if err != nil {
        panic(err)
    }

    // Register the trace exporter with a tracer provider
    bsp := sdktrace.NewBatchSpanProcessor(traceExporter)
    tracerProvider := sdktrace.NewTracerProvider(
        sdktrace.WithSampler(sdktrace.AlwaysSample()),
        sdktrace.WithSpanProcessor(bsp),
    )

    otel.SetTracerProvider(tracerProvider)

    // set global propagator to tracecontext
    otel.SetTextMapPropagator(propagation.TraceContext{})

    return tracerProvider.Shutdown
}

また、CronJob やバックグランド処理などアプリケーション発信の処理の場合はトレースコンテキストを初期化する必要があります。 その場合は以下のような実装にできます。

package main

// ...

func main() {
    ctx := context.Background()

    // setup trace exporter
    shutdown := setupTraceExporter(ctx)
    defer shutdown(ctx)

    // execute job
    executeJob(ctx)
}

func executeJob(ctx context.Context) {
    // create a new root span
    ctx, span := otel.Tracer("").Start(ctx, "MyJob")
    defer span.End()

    // setup tracing context from root span
    sc := span.SpanContext()

    tracing := tracectx.Tracing{
        B3TraceID: sc.TraceID().String(),
        B3SpanID:  sc.SpanID().String(),
    }

    // Add tracing info to context
    ctx = tracectx.AddToContext(ctx, tracing)

    // process
    // ...
}

Golang でのデータベーストレース

otelsql や otelsqlx ライブラリを使えば SQL データベースのクエリトレーシングが非常にシンプルに実装可能です。 注意点として、クエリを実行する際に db.Select(...) ではなく ctx を渡している db.SelectContext(ctx, ...) 関数を利用しないとクエリのトレース情報を他のトレース情報とうまく紐付けられないです。

import (
    "github.com/jmoiron/sqlx"
    "github.com/uptrace/opentelemetry-go-extra/otelsql"
    "github.com/uptrace/opentelemetry-go-extra/otelsqlx"
    semconv "go.opentelemetry.io/otel/semconv/v1.24.0"
)

func NewDatabase() (*sqlx.DB, error) {
    return otelsqlx.Connect(
        "pgx", "postgres://my-user:my-password@my-host:5432/my-database",
        otelsql.WithAttributes(semconv.DBSystemPostgreSQL),
        otelsql.WithDBName("my-database"),
    )
}

redisotel ライブラリを使えば Redis のクエリトレーシングもとても楽です。 注意点として、本番環境などで get や set のクエリ内容がトレース情報に残らないように redisotel.WithDBStatement(false) を設定する必要があります。

import (
    "context"
    "github.com/redis/go-redis/extra/redisotel/v9"
    "github.com/redis/go-redis/v9"
)

func NewRedisClient(ctx context.Context) (*redis.ClusterClient, error) {
    options := redis.ClusterOptions{
        Addrs:    "127.0.0.1:6379",
        Username: "my-user",
        Password: "my-password",
    }

    client := redis.NewClusterClient(&options)

    tracingOptions := []redisotel.TracingOption{
        // not setting to false will show full statements in traces
        redisotel.WithDBStatement(true),
    }

    if err := redisotel.InstrumentTracing(client, tracingOptions...); err != nil {
        return nil, err
    }

    if _, err := client.Ping(ctx).Result(); err != nil {
        return nil, err
    }

    return client, nil
}

トレースのサンプル

Istio の設定、OpenTelemetry Collector の設定、Golang の実装が一通り完了したら以下のようなトレース情報が取れるようになります！ トレースサンプル

リクエストの流れを簡単に説明すると：

  • クライアントが GKE クラスタで動いている user-service に GetUser gRPC リクエストを送る
  • user-service が Redis から情報を get する
  • user-service が EKS で動いている auth-service に Authenticate gRPC リクエストを送る
  • auth-service が SQL データベースにクエリを実行する
  • auth-service が user-service にレスポンスを返す
  • user-service が Redis にデータを set する
  • user-service が同じ GKE クラスタで動いている geo-service に Geolocate gRPC リクエストを送る
  • geo-service が Redis からデータを取得する ( myFunction 内部関数の実行時間も計測している )
  • geo-service が user-service にレスポンスを返す
  • user-service がレスポンスを返す

また、それぞれのスパンの詳細を見ると実行されたクエリを確認できとても便利です！

トレース詳細サンプル

最後に

分散トレーシングを利用することで複雑なリクエスト処理の流れを簡単に可視化でき、パフォーマンスのボトルネックとエラーの発生箇所など様々なインサイトを得られます。

GO株式会社では以下の構成で Golang マイクロサービスの徹底的な分散トレーシングを実現しています。

  • Istio サービスメッシュで HTTP/gRPC リクエストのトレースを取得
  • データベースクエリや内部関数などサービス内のトレース情報を Golang で出力
  • トレースコンテキストの伝搬を Golang で行う
  • OpenTelemetry Collector でトレース情報を加工し Grafana Tempo に送信
  • トレース情報を Grafana で閲覧

一部の情報をサービスメッシュから取得しているものの徹底的なトレース情報を取得するにはサービス内の実装がまだそれなりに必要です。 現時点では成熟度が少し足りなくて本番での利用を控えていますが今後 Grafana Beyla など eBFF ベースで言語アグノスティックなソリューションを検討したいと思います。