開発を加速させるGOGENのオブザーバビリティ

2024年7月16日 15:25

GOGEN プロダクト部ソフトウェアエンジニアの赤嶺(@kazz187)です。
我々のチームは、お客様にいち早く価値を提供するために、開発環境で動作確認するときやデプロイしたときのエラーを迅速に察知し、内容を把握し、修正できる仕組みを整え、不具合対応を煩雑な作業ではなく、その場で迅速に解決できるような気軽なものとしています。
どのようにそれらを実現しているかを本記事では紹介します。

なぜオブザーバビリティが大事なのか

我々GOGENプロダクト部は、少人数での効率的な開発を重視しています。限られたリソースで最大の価値を生み出すため、私たちは常に時間の有効活用を考えています。その中で、オブザーバビリティ（可観測性）の確保が非常に重要です。

システム開発において、エラーや障害との戦いは避けられません。しかし、その対応に費やす時間は可能な限り削減し、本質的な価値創造に集中すべきです。

オブザーバビリティの確保は、確かに初期段階では追加の作業やコストを必要とします。しかし、これは将来的な時間とリソースの大幅な節約につながる重要な投資です。CTOの楠本（@zabio3）は、「開発者の時間は貴重だ。本質的な価値創造に集中するため、オブザーバビリティは重要である。だからこそ、問題検知と初期分析を効率化し、可視化することが不可欠。」という方針は、我々の開発プラクティスの基盤となっています。この考えに基づき、適切なモニタリングツールとプラクティスを導入することで、後々のエラー調査や障害対応の時間を劇的に短縮できます。

我々のチームでは少人数で最小限の管理コストでオブザーバビリティを確保するために、便利にDatadogを最大限活用することを選択しました。
本記事ではオブザーバビリティをメトリクス、トレーシング、ロギングの3点に噛み砕いて、我々がどのようにチャレンジしてきたのかをご紹介します。

メトリクス

基本的なメトリクスはECSを通してCloudWatchに集約されるのですが、我々のサービスではバックエンド開発にGo言語を利用しており、基本的なCloudWatchのメトリクスだけでは到底、障害対応に立ち向かう事ができません。
そこでDatadog Metricsにカスタムメトリクスを送信することで障害対応に備えることにしました。
Go言語でサービスを開発するときに我々が取得しているメトリクスの例を紹介します。

1. 実際のメモリ使用量

Go言語にはGCが存在するため、ECS経由で取得できるメモリ使用量は実際に利用されているメモリ利用量よりもはるかに大きい値であり、なかなか開放されません。そのため、実際にどれだけのメモリが必要とされているのかを測ることができません。これは長期的なメモリリークなどを調査するときに困ります。

2. goroutine の数

Go言語を用いてユーザーのリクエスト時間が長くなる傾向のあるチャットなどのリアルタイムなサービスを開発するときや、簡単な非同期処理を行う際などに、goroutineを活用する場合がありますが、その際、現在サーバー上で実行されているgoroutineの数を気にする必要があります。goroutineリークが起きないように気をつけないといけません。

3. MySQLへの接続数

Go言語ではMySQLへの接続にはコネクションプールが使われますが、それらが意図したとおりのコネクション数を保っているかを確認する必要があります。AuroraなどのAmazon RDSへの接続数はインスタンスサイズによりシビアに固定されており、サービスがまだ小さなフェーズだと、合わせて小さなインスタンスを利用するケースも多く、MaxConnectionsエラーに引っかかりがちです。これらもしっかり監視する必要があります。

どのようにメトリクスを取得しているか

アプリのコンテナからPrometheusのライブラリpromhttpを用いてOpenMetrics形式で出力し、Datadog AgentのOpenMetrics Integrationでその値を定期的にポーリングしてもらい、Datadog Metricsへ送信しています。
promhttpを利用すれば、デフォルトでメモリ利用量やgoroutine数など、Goのランタイムの必須メトリクスを取得することができます。
MySQLのコネクション数の取得にはdlmiddlecote/sqlstatsを利用しています。

トレーシング

トレーシングはリクエストあたりのログの量を少なくするのに非常に役立ちます。
処理の開始と終わりをスパンという単位で計測し、スパンの親子関係でサービスやリソースの依存関係を表現できます。
つまり、都度詳細なログを仕込まなくても、リクエストの内部でどのようなサービス・リソースを呼び出しており、それにどのくらいの時間がかかっているか、どのようなクエリが実行されたのかなどが詳細に記録されるのです。
エラーが起きたときにどこのスパンでエラーが起きているのかも一目瞭然です。1リクエストに必要な情報が1つのトレースに集約されるため、膨大なログの中から必要なログを探し出す作業はもう必要ありません。

OpenTelemetry

Datadog Traces向けにトレースを取得する方法にはdd-trace-goを利用するなどいくつかあるのですが、我々のチームではOpenTelemetryという共通規格の実装を用いることにし、今後Datadog以外の便利なツールが出てきたときにそこにもトレースログを送信できるようにしています。
OpenTelemetryはdd-trace-goとは違って、利用しているライブラリごとのライブラリを探して利用する必要があります。(もちろん独自のサービス・リソースのスパン用のライブラリを自作することもできます。)
我々が実際に利用しているOpenTelemetryライブラリをいくつか紹介します。

connect-go: connectrpc.com/otelconnect
- Buf Connect 用のライブラリ
chi: github.com/riandyrn/otelchi
- http サーバー chi 用のライブラリ
bun: github.com/uptrace/bun/extra/bunotel
- bun ORM 用のライブラリ
aws: go.opentelemetry.io/contrib/instrumentation/github.com/aws/aws-sdk-go-v2/otelaws
- AWS SDK 用のライブラリ
http: go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp
- 外部サービスを実行するHTTP Client用のライブラリ
gRPC exporter: go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc
- Datadog Agent へのトレースログ出力用のライブラリ
標準出力 exporter: go.opentelemetry.io/otel/exporters/stdout/stdouttrace
- ローカル環境でのトレースログデバッグ用

トレーシングを複数サービスに横展開するための取り組み

トレースログを出力するためにOpenTelemetry関連の処理を記述することをメンバーに押し付けることで認知負荷を高めてしまい、サービス開発に集中できなくなることがあっては開発速度を下げてしまうことに繋がります。
GOGEN ecosystem ライブラリを作ることでトレーシングに関連する処理を複数サービスに横展開する取り組みを行っています。
いくつかそのライブラリの内容をご紹介します。

1) connect-goのリクエスト毎のスパン作成をInterceptorにまとめた例

package ddotel

import (
	"context"
	"errors"

	"connectrpc.com/connect"
	"go.opentelemetry.io/otel/attribute"

	"github.com/GOGEN-Inc/release/backend/pkg/cerr"
	"github.com/GOGEN-Inc/release/backend/pkg/clog"
)

const (
	DDAttributeErrorStackKey   = attribute.Key("error.stack")
	DDAttributeErrorMessageKey = attribute.Key("error.message")
)

func NewConnectTraceLogUnaryInterceptor() connect.UnaryInterceptorFunc {
	return func(next connect.UnaryFunc) connect.UnaryFunc {
		return func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) {
			span := injectTraceAttributes(ctx, "connect.server")
			resp, err := next(ctx, req)
			if err != nil {
				cErr := &cerr.Error{}
				if errors.As(err, &cErr) {
					if clog.ConnectCodeToLevel(cErr.ConnectError().Code()) == clog.LevelError {
						span.SetAttributes(DDAttributeErrorMessageKey.String(err.Error()))
						if cErr.Stack != "" {
							span.SetAttributes(DDAttributeErrorStackKey.String(cErr.Stack))
						}
					}
				} else {
					span.SetAttributes(DDAttributeErrorMessageKey.String(err.Error()))
				}
			}
			return resp, err
		}
	}
}

2) Auth0へのリクエストスパンをコンストラクタにまとめた例

package auth0

import (
	"net/http"

	"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
	"go.opentelemetry.io/otel/attribute"
	semconv "go.opentelemetry.io/otel/semconv/v1.18.0"
	"go.opentelemetry.io/otel/trace"
)

func NewAuth0ClientWithTracer(cfg *Config) Client {
	auth0Http := &http.Client{
		Transport: otelhttp.NewTransport(
			http.DefaultTransport,
			otelhttp.WithSpanOptions(trace.WithAttributes(
				attribute.KeyValue{
					Key:   "operation.name",
					Value: attribute.StringValue("auth0.http"),
				},
				semconv.ServiceName(cfg.ServiceName),
			)),
		),
	}
	client, err := NewClient(cfg, auth0Http)
	if err != nil {
		panic(err)
	}
	return client
}

このようにInterceptorを差し込むだけ、またはコンストラクタをDIするだけで各所のスパンが生成されるような仕組みを提供し、機能開発時にOpenTelemetry関連ライブラリ群と他のエンジニアが格闘する必要がないようにしています。

エラーログが出たときにスタックトレースを取得する重要性

Go標準のエラーではエラーが出たときにスタックトレースが出力されないため、どこでエラーが起きたかが一見してわかりません。
エラーを返すときは`fmt.Errorf()`などを用いてWrapするルールを敷いているのですが、それでもエラー調査時の手間がかかります。

そこで我々は独自のエラー型をecosystemライブラリ内で定義することで対応しました。
エラーをNewするときにスタックトレースを取得する仕組みを作りました。

package cerr

import (
	"bytes"
	"context"
	"encoding/json"
	"errors"
	"fmt"
	"net"
	"net/http"
	"runtime"

	"connectrpc.com/connect"
	"google.golang.org/protobuf/proto"

	"github.com/GOGEN-Inc/release/backend/pkg/clog"
)

type Error struct {
	Code    Code
	Msg     string          // ユーザーへ Code とともに返却するメッセージ
	Err     error           // ログに残したいエラー
	Stack   string          // スタックトレース
	Details []proto.Message // ユーザーへ返却したい詳細なエラー
}

func NewError(code Code, msg string, wrap error) *Error {
	err := &Error{
		Code: code,
		Msg:  msg,
		Err:  wrap,
	}
	if clog.ConnectCodeToLevel(code.ConnectCode()) == clog.LevelError {
		stackTrace := make([]byte, 2048)
		n := runtime.Stack(stackTrace, false)
		err.Stack = string(stackTrace[0:n])
	}
	return err
}

このようにNewするときにログレベルがErrorだった場合にはスタックトレースを取得して含めるようにしています。
エラーをプロジェクト内で共通フォーマット化することにより、ログレベルの指定、ユーザーに返却するメッセージの作成、ログに出力するエラーのラップ、必要に応じたスタックトレースの作成などを一元管理することができます。
これらの情報を利用し、トレースログにエラーやスタックトレースを出力しています。 (先ほど示した「1) connect-goのリクエスト毎のスパン作成をInterceptorにまとめた例」を参考にしてください。)

スタックトレースを出力するとDatadogとGitHubのコードを連携できる

Datadog TracesにはGitHub連携機能というのがあり、トレースログにスタックトレースがアタッチされていた場合、スタックトレースの箇所のソースコードをDatadog Traces上で見ることができます。
つまりGitHubやIDEを開かなくても、エラーアラートが飛んできたときに、Datadogだけでエラーの原因に当たりをつけることができるのです。外出先でもスマホひとつで障害の一次対応ができたりします。これは少人数でサービスを運用するに当たり非常に強力な機能です。
この機能を利用するときはデプロイ時のタスク定義にGitのrepository_urlとcommitハッシュを含め、トレースログにそれらのデータを出力する必要があります。
これらはすべてのトレースログにおいて共通のattributeなのでExporter内で指定しておけば大丈夫です。

package ddotel

import (
	"context"
	"fmt"

	"go.opentelemetry.io/otel"
	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc"
	"go.opentelemetry.io/otel/exporters/stdout/stdouttrace"
	"go.opentelemetry.io/otel/propagation"
	"go.opentelemetry.io/otel/sdk/resource"
	"go.opentelemetry.io/otel/sdk/trace"
	semconv "go.opentelemetry.io/otel/semconv/v1.18.0"
)

type InitGlobalTracerInput struct {
	Env          string
	DebugTracing bool
	ServiceName  string
	Version      string
	GitCommitSHA string
	GitRepo      string
}

func InitGlobalTracer(input *InitGlobalTracerInput) error {
	var exporter trace.SpanExporter
	if input.Env == "local" {
		// ローカルで DebugTracing が true の場合、 stdout にトレースを export する。
		if input.DebugTracing {
			var err error
			exporter, err = stdouttrace.New(stdouttrace.WithPrettyPrint())
			if err != nil {
				return fmt.Errorf("failed to initialize stdout exporter: %w", err)
			}
		}
	} else {
		// ローカル以外、 Datadog agent 向けにトレースを export する。
		var err error
		exporter, err = otlptracegrpc.New(
			context.Background(),
			otlptracegrpc.WithInsecure(),
		)
		if err != nil {
			return fmt.Errorf("failed to initialize otlptrace exporter: %w", err)
		}
	}
	res := resource.NewWithAttributes(
		semconv.SchemaURL,
		semconv.ServiceName(input.ServiceName),
		semconv.ServiceVersion(input.Version),
		attribute.KeyValue{
			Key:   "git.commit.sha",
			Value: attribute.StringValue(input.GitCommitSHA),
		},
		attribute.KeyValue{
			Key:   "git.repository_url",
			Value: attribute.StringValue(input.GitRepo),
		},
	)
	opts := []trace.TracerProviderOption{
		trace.WithSampler(trace.AlwaysSample()),
		trace.WithResource(res),
	}
	if exporter != nil {
		opts = append(opts, trace.WithBatcher(exporter))
	}
	tp := trace.NewTracerProvider(opts...)
	otel.SetTracerProvider(tp)
	otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator(propagation.TraceContext{}, propagation.Baggage{}))
	return nil
}

ロギング

Go標準ロガーであるslogを利用して、構造化ログを出力するようにしています。基本的にリクエストのログは1リクエスト1ログに限定して、出力したいカスタム値がある場合はリクエストContext内のattributes mapに値を追加し、リクエストの最後にInterceptor内でまとめて1回だけ出力する仕組みを取っています。

カスタムロガーの作成

slogを直接利用するのではなく、gRPC ecosystemのロガーを参考にリクエストContext内にロガーとattributesを入れて持ち運ぶライブラリを作成して利用しています。

package clog

import (
	"context"
	"log/slog"
	"sync"
)

type ctxSlog struct {
	logger     *slog.Logger
	mu         sync.RWMutex
	attributes map[string]any
}

type ctxSlogKey struct{}

func ContextWithSlog(ctx context.Context, logger *slog.Logger) context.Context {
	ctxSlog := &ctxSlog{
		logger:     logger,
		attributes: make(map[string]any),
	}
	return context.WithValue(ctx, ctxSlogKey{}, ctxSlog)
}

func Extract(ctx context.Context) *slog.Logger {
	l, ok := ctx.Value(ctxSlogKey{}).(*ctxSlog)
	if !ok {
		return slog.Default()
	}
	logger := l.logger
	var attrs []any
	for k, v := range l.attributes {
		attrs = append(attrs, k, v)
	}
	logger = logger.With(attrs...)
	return logger
}

func AddAttributes(ctx context.Context, attributes map[string]any) {
	l, ok := ctx.Value(ctxSlogKey{}).(*ctxSlog)
	if !ok {
		return
	}
	l.mu.Lock()
	defer l.mu.Unlock()
	for k, v := range attributes {
		l.attributes[k] = v
	}
}

const (
	MessageAttributeKey = "msg"
	ErrorAttributeKey   = "error.message"
	StackAttributeKey   = "error.stack"
)

func AddError(ctx context.Context, err error) {
	l, ok := ctx.Value(ctxSlogKey{}).(*ctxSlog)
	if !ok {
		return
	}
	l.mu.Lock()
	defer l.mu.Unlock()
	l.attributes[ErrorAttributeKey] = err
}

func GetError(ctx context.Context) error {
	l, ok := ctx.Value(ctxSlogKey{}).(*ctxSlog)
	if !ok {
		return nil
	}
	l.mu.RLock()
	ierr, ok := l.attributes[ErrorAttributeKey]
	l.mu.RUnlock()
	if !ok {
		return nil
	}
	err, ok := ierr.(error)
	if !ok {
		return nil
	}
	return err
}

func AddMsg(ctx context.Context, msg string) {
	l, ok := ctx.Value(ctxSlogKey{}).(*ctxSlog)
	if !ok {
		return
	}
	l.mu.Lock()
	defer l.mu.Unlock()
	l.attributes[MessageAttributeKey] = msg
}

func GetMsg(ctx context.Context) string {
	l, ok := ctx.Value(ctxSlogKey{}).(*ctxSlog)
	if !ok {
		return ""
	}
	l.mu.RLock()
	msg, ok := l.attributes[MessageAttributeKey].(string)
	l.mu.RUnlock()
	if !ok {
		return ""
	}
	return msg
}

func delMsg(ctx context.Context) {
	l, ok := ctx.Value(ctxSlogKey{}).(*ctxSlog)
	if !ok {
		return
	}

	l.mu.Lock()
	defer l.mu.Unlock()
	if _, ok := l.attributes[MessageAttributeKey]; !ok {
		return
	}
	delete(l.attributes, MessageAttributeKey)
}

func AddStack(ctx context.Context, stack string) {
	l, ok := ctx.Value(ctxSlogKey{}).(*ctxSlog)
	if !ok {
		return
	}
	l.mu.Lock()
	defer l.mu.Unlock()
	l.attributes[StackAttributeKey] = stack
}

func GetStack(ctx context.Context) string {
	l, ok := ctx.Value(ctxSlogKey{}).(*ctxSlog)
	if !ok {
		return ""
	}
	l.mu.RLock()
	iStack, ok := l.attributes[StackAttributeKey]
	l.mu.RUnlock()
	if !ok {
		return ""
	}
	stack, ok := iStack.(string)
	if !ok {
		return ""
	}
	return stack
}

実際のロジック内では下記のコードを用いてロギングを行います。

package clog

import (
	"context"
	"fmt"
)

func Debug(ctx context.Context, msg string, args ...any) {
	Extract(ctx).DebugContext(ctx, msg, args...)
}

func Debugf(ctx context.Context, format string, args ...any) {
	Extract(ctx).DebugContext(ctx, fmt.Sprintf(format, args...))
}

func Info(ctx context.Context, msg string, args ...any) {
	Extract(ctx).InfoContext(ctx, msg, args...)
}

func Infof(ctx context.Context, format string, args ...any) {
	Extract(ctx).InfoContext(ctx, fmt.Sprintf(format, args...))
}

func Warn(ctx context.Context, msg string, args ...any) {
	Extract(ctx).WarnContext(ctx, msg, args...)
}

func Warnf(ctx context.Context, format string, args ...any) {
	Extract(ctx).WarnContext(ctx, fmt.Sprintf(format, args...))
}

func Error(ctx context.Context, msg string, args ...any) {
	Extract(ctx).ErrorContext(ctx, msg, args...)
}

func Errorf(ctx context.Context, format string, args ...any) {
	Extract(ctx).ErrorContext(ctx, fmt.Sprintf(format, args...))
}

Datadog Tracesとの連携

Datadog Tracesとログを連携させるために、dd.trace_idというattributeを構造化ログに含める必要があります。これを含めておくと、各トレース画面からリクエスト内のすべてログをリストアップできたり、ログからトレース画面へ飛ぶことができるようになります。

このようにトレースを作成するときにロガーのattributeにトレースIDを関連付けておくことで、すべてのログにトレースIDを含めることができます。

package ddotel

import (
	"context"
	"strconv"

	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/trace"

	"github.com/GOGEN-Inc/release/backend/pkg/clog"
)

func injectTraceAttributes(ctx context.Context, opsName string) trace.Span {
	spanCtx := trace.SpanContextFromContext(ctx)
	traceID := spanCtx.TraceID()
	spanID := spanCtx.SpanID()
	ddTraceID := OtelTraceIDToUint64(traceID)
	ddSpanID := OtelSpanIDToUint64(spanID)

	// Inject trace ID into log attributes
	clog.AddAttributes(ctx, map[string]any{
		"otel.trace_id": traceID.String(),
		"dd.trace_id":   strconv.FormatUint(ddTraceID, 10),
		"dd.span_id":    strconv.FormatUint(ddSpanID, 10),
	})

	// Inject operation name into span attributes for Datadog APM
	span := trace.SpanFromContext(ctx)
	span.SetAttributes(attribute.KeyValue{
		Key:   "operation.name",
		Value: attribute.StringValue(opsName),
	})
	return span
}

DatadogとOpenTelemetryでトレースIDの型が異なる問題

DatadogとOpenTelemetryでトレースIDの型が異なるため、適宜変換する必要があります。基本的にOpenTelemetry -> Datadogの方向でしか変換する必要はありません。

Datadog: uint64
OpenTelemetry: [16]byte

package ddotel

import "encoding/binary"

// OpenTelemetry と Datadog の TraceID と SpanID の変換
// dd-agent 準拠で変換する
// https://github.com/DataDog/datadog-agent/blob/47e3e537dae47ec704b2de7e06c20dbf3e166aee/pkg/trace/api/otlp.go#L676-L682

func OtelTraceIDToUint64(b [16]byte) uint64 {
	return binary.BigEndian.Uint64(b[len(b)-8:])
}

func OtelSpanIDToUint64(b [8]byte) uint64 {
	return binary.BigEndian.Uint64(b[:])
}

ここではDatadog Agentが内部で行っている変換ロジックを参考にしました。OpenTelemetryの16 bytes中、8 bytesのみを利用してuint64に変換しています。

ログをどのようにDatadogに送信しているか

ECSにはFirelensという機能があり、コンテナの標準出力をサイドカーに戻す機能があります。
サイドカーでfluentbitを起動しており、そこでJSONで出力された構造化ログをパースし、Datadogに送信するようにしています。
Datadogで送信すると同時にfirehose経由でS3にもログを保存しています。このため、Datadog Logsが障害のときもログを欠損させずにS3に保存することができます。

まとめ

本記事ではGOGENプロダクト部で行っているオブザーバビリティの実践例を、メトリクス、トレーシング、ロギングの3つに分けてご紹介しました。
実際のコード例も示しておりますので、皆様のオブザーバビリティの向上のお役に立てれば嬉しいです。

この他にも、DatadogにはプロファイリングやRUM(Real User Monitoring)など、運用を楽にしてくれる便利な機能がたくさんあります。これらの実践例も知見が溜まりましたら共有していきたいです。

日々の運用を楽にし、本来の取り組むべき価値に集中できる開発環境を作っています！一緒に、価値あるものづくりをしている仲間を募集しています！
少しでも興味を持たれた方は、ぜひお気軽にご連絡ください。カジュアルに話しましょう。

私たちGOGENは、技術を通じて真の価値を生み出すことに情熱を注いでいます。同じ想いを持つ仲間を探しています！少しでも「面白そう」と思った方、ぜひ気軽に連絡してください。堅苦しい面接じゃなくて、フランクにお話しできればと思います。

一緒に、もっとワクワクするようなものづくりをしませんか？お待ちしています！

この記事が気に入ったらサポートをしてみませんか？