これは GCP Advent Calendar 2023 および CastingONE Advent Calendar 2023 22日目の記事です。
はじめに
株式会社CastingONEでソフトウェアエンジニアをしている @takashabe です。普段はHR領域のSaaSをGoで書いています。
弊社ではアプリケーション実行基盤としてGoogle CloudのCloud Runを全面的に採用しています。マネージドを利用することで、非常に充実したインフラ運用周りのサポートが得られ、アプリケーション開発に注力することができています。
一方、アプリケーションの稼働状況が分かるようなログやトレース情報を出力できるのは、やはりアプリケーションを実際に開発している開発者が一番得意とするところです。ここではそういったログやトレースを紐づけて閲覧出来るようにすることで、よりアプリケーションの状況を観測しやすくするための仕組みについて紹介します。
また本記事のサンプルコードは以下にあります。
Cloud Loggingの構造化ロギングについて
Cloud LoggingではJSONオブジェクトでログを出力する際、特定のフィールドがメタ情報として使用されます。これらはCloud Logging上でグルーピングするために使用されたりと特別な意味を持ちます。
Cloud Runからログを出力するときにもこれらのフィールドが自動的に付与されることで、扱いやすいログを出力してくれます。
severtity などは特にエラーやワーニングを探すときに重宝するので身近ではないでしょうか。
traceフィールドにtrace_idを紐づける
さて、ここで今回の本題である trace フィールドに着目したいと思います。
Cloud Runではリクエストを受け付けるたびにトレースIDが発行され、Cloud Traceにトレース情報が出力されます。traceフィールドは projects/<PROJECT_ID>/traces/<TRACE_ID> の形を取り、Cloud Logging / Cloud TraceのUI上から相互に参照することができるようになります。
ログとトレースを紐づける
ここまではCloud Runが自動で出力してくれるログとトレースを見てきました。そしてそれを相互に参照するためにtraceフィールドなどの仕組みがあることがわかりました。
では実際にアプリケーションから任意に出力するログとトレースを、前述のような期待する形で出力するための実装を見ていきたいと思います。
サンプル実装はGoで、otelとzerologを使用します。
まずはトレース関連を担うotelを使った実装についてです。全体的にcontextを使ってトレース情報をやり取り出来るような薄いラッパー実装だけです。各種パッケージを直接使っても良いですが、取り回しがしやすいので普段からこのような感じの実装を使っています。
package main
import (
"context"
"log"
"net/http"
"os"
texporter "github.com/GoogleCloudPlatform/opentelemetry-operations-go/exporter/trace"
"go.opentelemetry.io/otel"
"go.opentelemetry.io/otel/propagation"
"go.opentelemetry.io/otel/sdk/resource"
sdktrace "go.opentelemetry.io/otel/sdk/trace"
semconv "go.opentelemetry.io/otel/semconv/v1.7.0"
"go.opentelemetry.io/otel/trace"
)
// InitTracer TraceProviderの初期化
func InitTracer(ctx context.Context) (shutdown func(context.Context) error) {
projectID := os.Getenv("PROJECT_ID")
otel.SetTextMapPropagator(propagation.TraceContext{})
exporter, err := texporter.New(texporter.WithProjectID(projectID))
if err != nil {
log.Fatalf("texporter.New: %v", err)
}
tp := sdktrace.NewTracerProvider(
sdktrace.WithBatcher(exporter),
sdktrace.WithSampler(sdktrace.AlwaysSample()),
sdktrace.WithResource(resource.NewWithAttributes(
semconv.SchemaURL,
semconv.ServiceNameKey.String("run-o11y-sample"),
)),
)
otel.SetTracerProvider(tp)
return tp.Shutdown
}
// SpanFromHeader HTTPヘッダからトレース情報を取得
func SpanFromHeader(ctx context.Context, header http.Header) context.Context {
return otel.GetTextMapPropagator().Extract(ctx, propagation.HeaderCarrier(header))
}
// StartSpan Spanの記録の開始
func StartSpan(ctx context.Context, name string) context.Context {
tr := otel.GetTracerProvider().Tracer("run-o11y-sample")
cctx, _ := tr.Start(ctx, name)
ctx = cctx
return ctx
}
// SpanFromContext ContextからSpanを取得
func SpanFromContext(ctx context.Context) trace.Span {
return trace.SpanFromContext(ctx)
}
// EndSpan Spanの記録の終了
func EndSpan(ctx context.Context) {
trace.SpanFromContext(ctx).End()
}
つぎにログ出力を担うzerologの実装です。zerologのCloud Logging向けラッパーであるzerodriverを使っています。
zerodriverでは TraceContext() メソッドを使ってトレース関連のフィールドを出力出来るので、contextを元にトレース情報を引き出して、適宜埋めてやるだけで実装完了です。
package main
import (
"context"
"os"
"github.com/hirosassa/zerodriver"
)
var logger = zerodriver.NewProductionLogger()
// info インフォログの出力
func info(ctx context.Context, msg string) {
span := SpanFromContext(ctx)
logger.Info().
TraceContext(span.SpanContext().TraceID().String(), span.SpanContext().SpanID().String(), true, os.Getenv("PROJECT_ID")).
Msg(msg)
}
最後にmainの実装です。ここでは1つだけハンドラを設定しており、Cloud Runが自動的に付与してくれるHTTPヘッダのトレース情報を伝播し、適宜ログとトレースを出力するような感じです。
package main
import (
"context"
"net/http"
)
func main() {
ctx := context.Background()
fn := InitTracer(ctx)
defer func() {
fn(ctx)
}()
http.HandleFunc("/", traceHandle)
if err := http.ListenAndServe(":8080", nil); err != nil {
panic(err)
}
}
// traceHandle ヘッダからトレース情報を取得して、contextを伝播させる
func traceHandle(w http.ResponseWriter, r *http.Request) {
ctx := r.Context()
ctx = SpanFromHeader(ctx, r.Header)
defer func() { EndSpan(ctx) }()
run(ctx)
info(ctx, "log/traceHandle")
}
// run トレースとログを出力
func run(ctx context.Context) {
ctx = StartSpan(ctx, "trace/run")
defer func() { EndSpan(ctx) }()
info(ctx, "log/run")
run2(ctx)
}
// run2 トレースとログを出力その2
func run2(ctx context.Context) {
ctx = StartSpan(ctx, "trace/run2")
defer func() { EndSpan(ctx) }()
info(ctx, "log/run2")
}
そしてこのアプリケーションをCloud Runにデプロイし、リクエストを送ってみます。すると以下のように同一のtraceフィールドを持つ複数のログが得られると思います。
これで1つのログとトレースが紐づくのはもちろん、同一のトレースIDを持つログがspanと共にグループ化されました。実際のアプリケーションではリクエストスコープでトレースIDを引き回すことになると思うので、自ずと1つのリクエストでアプリケーションがどう動いているかが観測しやすくなります。
またmain.goのハンドラがそうであったように、基本的にHTTPヘッダにトレース情報を詰めて引き回すことによって、分散トレーシングとログの紐づけも簡単に実現できるでしょう。
おわりに
Cloud Run、Cloud Logging、Cloud Traceを題材にして、1リクエストにおけるログとトレースを紐づけて観測出来るようにする仕組みについて紹介しました。
Google Cloudだけでなく、Datadogなどでも基本的に同様のアプローチを使えるので、ぜひお手元の環境で試してみてください。
いつもの
株式会社CastingONE では、Observabilityを高めるのが好きなソフトウェアエンジニアを募集しております。Twitter(X)でもBlueskyでも良いのでお気軽にご連絡ください！
Discussion