Day 073 — 2026-10-13 | ミドルウェア設計パターン: OTel につないだ Edge を本番に寄せたら壊れた——上流のトレースが途切れる・比率サンプリングが上流の判断を無視する・WithGroup で trace_id がグループに潜る・応答後の監査が cancel で落ちる・探針が SLI を動かす、の 5 バグ

2026-10-13 🟡 上級者 / Phase 3 デバッグ・コードレビュー ミドルウェア設計パターン
フェーズ: 上級者 (Phase 3) | 問題タイプ: デバッグ・コードレビュー | テーマ: ミドルウェア設計パターン
Day 072 の次回予告どおり「デバッグ」。Day 072 の Edge(O1〜O11 は全部通る)を本番の構成に寄せるため、同僚が 3 つ足した: ① 本番の量に合わせた比率サンプリング、② /healthz をトレースから外す Filter、③ /export の監査ログを応答後に書く goroutine。Day 072 の 11 本は全部通ったまま、5 つのバグが入った。うち 2 つ(B1 propagator・B3 WithGroup)は Day 072 の模範解答にもともとあった。

📚 背景知識(読んでから問題へ)

今日の構成(Day 072 と同じ積む順)

上流 BFF ──traceparent──▶ otelhttp(span を作る・トレースだけ) → Edge(袋・3 出口に 1 回ずつ) → Identify → Recover → Adapt → ハンドラ
                                                                                                         └─ go 監査(応答後に書く)

用語

用語意味
traceparentW3C Trace Context のヘッダ。00-<trace_id 32 桁>-<親 span_id 16 桁>-<flags 2 桁>。flags の 01 は「上流はこのトレースを記録した(sampled)」
propagatorヘッダと ctx の間で trace の情報を出し入れする部品。Extract(ヘッダ→ctx)と Inject(ctx→ヘッダ)
samplerspan を記録するかを決める部品。TraceIDRatioBased(0.1) は trace_id から 10% を選ぶ。ParentBased(x) は親があれば親の判断に従い、親が無いときだけ x に聞く
探針(probe)Kubernetes の liveness・readiness のように、機械が定期的に叩く /healthz・/readyz。利用者の要求ではない
context.WithoutCancelGo 1.21 で入った関数。親の値(span・request_id)は引き継ぎ、cancel と期限だけを外した ctx を返す

今日使う実物(一次資料。2026-10-13 に手元のモジュールキャッシュと Go 1.27.2 のソースで読んだ)

実物今日に関わる所場所
otelhttp v0.70.0 の設定の既定Propagators: otel.GetTextMapPropagator()。WithPropagators の説明は "If this option isn't specified, then the global TextMapPropagator is used."config.go 55 行・105〜107 行
OTel の大域 propagator誰も otel.SetTextMapPropagator を呼ばなければ、"the default no-op propagation.TextMapPropagator" に流す=traceparent を読まないotel@v1.45.0/internal/global/propagator.go 13〜15 行
otelhttp の FilterFilter が false を返すと "Simply pass through to the handler"(span を作らずに next を呼ぶ)。Extract はその後handler.go 90〜98 行
otelhttp の公開入口WithPublicEndpointFn が true を返すと、外から来た trace を親にせず、新しい root を作って link にするhandler.go 104〜110 行、config.go 95〜99 行
SDK の samplerTraceIDRatioBased は trace_id の下位 8 バイトを 1 ビット右にずらして上限と比べるだけ(親を見ない)。SDK の既定は ParentBased(AlwaysSample())sdk@v1.45.0/trace/sampling.go 71〜74 行・96 行・185 行、provider.go 520 行
exemplar の既定フィルタTraceBasedFilter は SpanContextFromContext(ctx).IsSampled() だけを見るsdk/metric@v1.45.0/exemplar/filter.go 22〜24 行
slog の WithGroup"A Handler should treat WithGroup as starting a Group of Attrs that ends at the end of the log event."(グループを開いた後の属性は、行の終わりまで全部その中に入る)Go 1.27.2 log/slog/handler.go 72〜91 行
Request.Context"For incoming server requests, the context is canceled when the client's connection closes, … or when the ServeHTTP method returns."Go 1.27.2 net/http/request.go 354〜356 行、cancel の実体は server.go 2159 行 w.cancelCtx()
context.WithoutCancel"The returned context returns no Deadline or Err, and its Done channel is nil."(期限も無くなる)Go 1.27.2 context/context.go 581〜586 行

📝 問題

状況

Day 072 の edge.go に同僚が次の 3 つを足し、/export に監査を付けました。

  1. NewTracerProvider(sp, ratio): 本番は 1 日数千万要求なので、トレースは 10% だけ記録したい
  2. Traced に WithFilter: kubelet が 10 秒ごとに叩く /healthz の span が多すぎる
  3. app.go の Auditor: 監査ストアへの書き込みは遅いので、応答を待たせず goroutine で書く

Day 072 の O1〜O11 は -race 付きで全部通りました。レビューで、上流(BFF)チームとSRE からこう言われました。

  • 上流 BFF チーム: 「うちのトレースで、/export の span がほとんど出てこない。出てくるときも、うちが記録していないトレースの中に親の無い span がぽつぽつある」
  • SRE: 「ログを trace_id で検索しても、ハンドラが WithGroup("job") で書いた行が引っかからない」「監査ログが全件 audit failed: context canceled」「/export の可用性が、/readyz が落ちている起動直後に下がり、平常時は実際より高く出る」

課題

edge.go と app.go の 5 つのバグを見つけて直し、wire_test.go の D1〜D8 と Day 072 の O1〜O11 を -race 付きで全部通してください。テストは変えないこと。

テストが求めていること(括弧はテスト名):

約束テスト
上流が記録した(flags=01)トレースは、同じ trace_id・上流 span を親として記録するD1
上流が捨てた(flags=00)トレースは記録しない。ログの trace_id は上流と同じ。exemplar は付かないD2
traceparent が無ければ新しい root(基準線)D3
baggage ヘッダは ctx に入れない(基準線。直し方を広げすぎると落ちる)D4
log.With(…).WithGroup("job").With(…) で書いた行でも、trace_id・span_id・request_id は最上位D5
応答の後に走る監査が成功し、Edge の行と同じ trace_id・request_id を持つ(実サーバー)D6
監査にも上限がある。監査ストアが詰まったら Timeout で諦める(実サーバー)D7
探針(/healthz・/readyz)は span もメトリクスも作らず SLI に入らない。/readyz の失敗だけはログに残すD8

予想してから解く(自己評価欄へ)

  • P1: 比率 0.1 の TraceIDRatioBased だけを使うと、上流が記録した要求のうち何 % が自分の span も記録されるか。上流が捨てた要求のうち何 % が記録されるか
  • P2: WithGroup 問題を直すと、グループを使う行の 1 行あたりの割り当てはいくつ増えるか(直前は 48 B・2 allocs)
  • P3: バグ入りのまま、監査の goroutine は応答からどのくらい後に context canceled で落ちるか

準備

mkdir d73 && cd d73                                         # 作業ディレクトリを作って入る
printf 'module d73\n\ngo 1.24\n' > go.mod                   # モジュールを作る
go get go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp@v0.70.0 \
       go.opentelemetry.io/otel/sdk@v1.45.0 go.opentelemetry.io/otel/sdk/metric@v1.45.0  # OTel を入れる
# Day 069 の types.go・adapt.go、Day 071 の recover.go、Day 072 の bag.go・edge_test.go をそのまま置く(変えない)
# 下の edge.go(バグ入り)・app.go(バグ入り)・wire_test.go を保存する
go test -race -count=1 ./...                                # 最初は D1・D2・D5・D6・D7・D8 の 6 本が落ちる

ファイル: edge.go(バグ入り。Day 072 の模範解答に WithFilter と NewTracerProvider を足しただけ)

edge.go(225 行・バグ入り)
package main

import (
	"context"
	"crypto/rand"
	"encoding/hex"
	"log/slog"
	"net/http"
	"runtime/debug"
	"strconv"
	"time"

	"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/codes"
	"go.opentelemetry.io/otel/metric"
	metricnoop "go.opentelemetry.io/otel/metric/noop"
	"go.opentelemetry.io/otel/sdk/metric/metricdata"
	sdktrace "go.opentelemetry.io/otel/sdk/trace"
	"go.opentelemetry.io/otel/semconv/v1.43.0/httpconv"
	"go.opentelemetry.io/otel/trace"
)

// ---- ログ: ctx にある trace_id・span_id・request_id を、どの 1 行にも自動で足す ----

// LogHandler は包んだ slog.Handler の前に 1 段入るだけ。Edge 以外が slog に書いても同じ鍵が付く。
type LogHandler struct{ slog.Handler }

func NewLogHandler(h slog.Handler) *LogHandler { return &LogHandler{h} }

func (h *LogHandler) Handle(ctx context.Context, rec slog.Record) error {
	if sc := trace.SpanContextFromContext(ctx); sc.IsValid() {
		rec.AddAttrs(slog.String("trace_id", sc.TraceID().String()), slog.String("span_id", sc.SpanID().String()))
	}
	if o := outcomeFrom(ctx); o != nil {
		rec.AddAttrs(slog.String("request_id", o.RequestID))
	}
	return h.Handler.Handle(ctx, rec)
}
func (h *LogHandler) WithAttrs(as []slog.Attr) slog.Handler {
	return &LogHandler{h.Handler.WithAttrs(as)}
}
func (h *LogHandler) WithGroup(name string) slog.Handler {
	return &LogHandler{h.Handler.WithGroup(name)}
}

// requestID は来た X-Request-Id を、短く・安全な文字だけなら引き継ぐ。それ以外は作り直す。
func requestID(r *http.Request) string {
	if v := r.Header.Get("X-Request-Id"); validRequestID(v) {
		return v
	}
	var b [8]byte
	rand.Read(b[:])
	return hex.EncodeToString(b[:])
}

func validRequestID(s string) bool {
	if len(s) == 0 || len(s) > 64 {
		return false
	}
	for i := 0; i < len(s); i++ {
		c := s[i]
		if !('a' <= c && c <= 'z' || 'A' <= c && c <= 'Z' || '0' <= c && c <= '9' || c == '-' || c == '_' || c == '.') {
			return false
		}
	}
	return true
}

// ---- メトリクスとトレースの属性(OTel HTTP semconv に合わせる) ----

// AbortedErrorType は「送信後に切った・何も送らずに切った」の error.type。5xx はステータスの数字の文字列。
const AbortedErrorType = "aborted"

func errorTypeOf(status int, aborted bool) string {
	switch {
	case aborted:
		return AbortedErrorType
	case status >= 500:
		return strconv.Itoa(status)
	}
	return "" // 成功・4xx・499 には付けない(semconv: 成功なら SHOULD NOT)
}

// methodOf は未知のメソッドを _OTHER にまとめる(系列の数を有限に保つ。otelhttp と同じ扱い)。
func methodOf(m string) httpconv.RequestMethodAttr {
	switch m {
	case "GET", "HEAD", "POST", "PUT", "DELETE", "CONNECT", "OPTIONS", "TRACE", "PATCH":
		return httpconv.RequestMethodAttr(m)
	}
	return httpconv.RequestMethodOther
}

// Edge は Day 071 の Edge を OTel につないだもの。袋を作り、defer で 3 つの出口に 1 回ずつ書き、panic は投げ直す。
// 外側に otelhttp(トレースだけ)がある前提。span は otelhttp が作り、Edge は状態と属性を足すだけ。
func Edge(log *slog.Logger, mp metric.MeterProvider, routeOf func(*http.Request) string) func(http.Handler) http.Handler {
	dur, err := httpconv.NewServerRequestDuration(mp.Meter("d73/edge"))
	if err != nil {
		panic(err)
	}
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			start := time.Now()
			o := &Outcome{RequestID: requestID(r)}
			w.Header().Set("X-Request-Id", o.RequestID)
			ow := &obsWriter{ResponseWriter: w}
			r = r.WithContext(context.WithValue(r.Context(), outcomeKey{}, o))
			defer func() {
				p := recover()
				aborted := p != nil
				if aborted && p != http.ErrAbortHandler && o.Panic == nil {
					o.Panic, o.Stack = p, debug.Stack() // Recover の付け忘れ
				}
				status := ow.status // aborted で 0 のままなら「何も送らずに切った」。0 のまま出す
				if status == 0 && !aborted {
					status = http.StatusOK
					if r.Context().Err() != nil {
						status = StatusClientClosed
						ow.WriteHeader(status) // 外側の otelhttp に 499 を見せる。相手はもういないので届かない
					}
				}
				class, et := classOf(status, aborted), errorTypeOf(status, aborted)
				d, route := time.Since(start), routeOf(r)

				// メトリクス: 1 点。属性は method・scheme・route・status(送ったときだけ)・error.type(失敗のときだけ)
				attrs := make([]attribute.KeyValue, 0, 3)
				attrs = append(attrs, dur.AttrRoute(route))
				if status != 0 {
					attrs = append(attrs, dur.AttrResponseStatusCode(status))
				}
				if et != "" {
					attrs = append(attrs, dur.AttrErrorType(httpconv.ErrorTypeAttr(et)))
				}
				scheme := "http"
				if r.TLS != nil {
					scheme = "https"
				}
				dur.Record(r.Context(), d.Seconds(), methodOf(r.Method), scheme, attrs...)

				// トレース: otelhttp が届かない所(panic が通り抜ける場面)と、otelhttp が付けない error.type を足す
				span := trace.SpanFromContext(r.Context())
				if et != "" {
					span.SetAttributes(attribute.String("error.type", et))
				}
				if aborted {
					span.SetStatus(codes.Error, "aborted")
					if status != 0 {
						span.SetAttributes(attribute.Int("http.response.status_code", status))
					}
				}

				// ログ: 1 行。trace_id・request_id は LogHandler が足す
				level := slog.LevelInfo
				if class == ClassServerError || class == ClassAborted {
					level = slog.LevelError
				}
				la := make([]slog.Attr, 0, 9)
				la = append(la,
					slog.String("method", r.Method), slog.String("route", route),
					slog.Int("status", status), slog.String("class", class),
					slog.Int64("dur_us", d.Microseconds()), slog.String("user", o.User))
				if o.Err != nil {
					la = append(la, slog.String("err", o.Err.Error()))
				}
				if o.Panic != nil {
					la = append(la, slog.Any("panic", o.Panic), slog.String("stack", string(o.Stack)))
				}
				log.LogAttrs(r.Context(), level, "request", la...)
				if p != nil {
					panic(p)
				}
			}()
			next.ServeHTTP(ow, r)
		})
	}
}

// Traced は otelhttp をトレースだけに使って h を包む。何もしない MeterProvider を渡すので、
// http.server.request.duration を書くのは内側の Edge だけになる。
func Traced(h http.Handler, tp trace.TracerProvider, routeOf func(*http.Request) string) http.Handler {
	return otelhttp.NewHandler(h, "http.server",
		otelhttp.WithTracerProvider(tp),
		otelhttp.WithMeterProvider(metricnoop.NewMeterProvider()),
		otelhttp.WithFilter(func(r *http.Request) bool { return r.URL.Path != "/healthz" }), // 探針はトレースしない
		otelhttp.WithSpanNameFormatter(func(_ string, r *http.Request) string { return routeOf(r) }))
}

// NewTracerProvider は本番の量に合わせ、ratio の割合だけ記録する(例: 0.1 なら 10%)。
func NewTracerProvider(sp sdktrace.SpanProcessor, ratio float64) *sdktrace.TracerProvider {
	return sdktrace.NewTracerProvider(
		sdktrace.WithSpanProcessor(sp),
		sdktrace.WithSampler(sdktrace.TraceIDRatioBased(ratio)))
}

// Stack は otelhttp(トレースだけ)→ Edge → Identify → Recover → Adapt の順に積む。
func Stack(h HandlerE, log *slog.Logger, tp trace.TracerProvider, mp metric.MeterProvider, routeOf func(*http.Request) string) http.Handler {
	return Traced(Edge(log, mp, routeOf)(Identify(Recover(PanicInto)(Adapt(h, ErrInto)))), tp, routeOf)
}

// SLIFrom は Edge が書いたメトリクスだけから可用性を出す。
// 499 は分母から外し、error.type が付いた点(5xx と aborted)を失敗、それ以外(2xx・3xx・4xx)を成功に数える。
func SLIFrom(rm metricdata.ResourceMetrics) float64 {
	var valid, bad uint64
	for _, sm := range rm.ScopeMetrics {
		for _, m := range sm.Metrics {
			h, ok := m.Data.(metricdata.Histogram[float64])
			if m.Name != "http.server.request.duration" || !ok {
				continue
			}
			for _, dp := range h.DataPoints {
				if v, ok := dp.Attributes.Value("http.response.status_code"); ok && v.AsInt64() == StatusClientClosed {
					continue
				}
				valid += dp.Count
				if dp.Attributes.HasValue("error.type") {
					bad += dp.Count
				}
			}
		}
	}
	if valid == 0 {
		return 1
	}
	return float64(valid-bad) / float64(valid)
}

ファイル: app.go(バグ入り)

app.go(48 行・バグ入り)
package main

import (
	"context"
	"io"
	"log/slog"
	"net/http"
	"sync"
	"time"
)

// Auditor は「誰が何を書き出したか」を監査ログに残す。書き込みは遅い(外部の監査ストアの代役)ので、
// 応答を待たせないよう別の goroutine で行う。
type Auditor struct {
	Log     *slog.Logger
	Delay   time.Duration // 監査ストアへの書き込みにかかる時間
	Timeout time.Duration // 監査 1 件の上限。要求の ctx から cancel を外すので、期限は自分で持つ
	wg      sync.WaitGroup
}

// Go は監査の書き込みを別 goroutine で始める。ctx は書き込みの期限と、ログの鍵(trace_id・request_id)を運ぶ。
func (a *Auditor) Go(ctx context.Context, user, what string) {
	a.wg.Add(1)
	go func() {
		defer a.wg.Done()
		ctx, cancel := context.WithTimeout(ctx, a.Timeout)
		defer cancel()
		select {
		case <-time.After(a.Delay):
		case <-ctx.Done():
			a.Log.ErrorContext(ctx, "audit failed", "user", user, "what", what, "err", ctx.Err().Error())
			return
		}
		a.Log.InfoContext(ctx, "audit", "user", user, "what", what)
	}()
}

// Wait はテストと停止処理のために、始めた書き込みがすべて終わるのを待つ。
func (a *Auditor) Wait() { a.wg.Wait() }

// Export は /export のハンドラ。CSV を返し、監査を残す。
func Export(a *Auditor) HandlerE {
	return func(w http.ResponseWriter, r *http.Request) error {
		a.Go(r.Context(), r.Header.Get("X-User"), "export")
		io.WriteString(w, "id,name\n1,alice\n")
		return nil
	}
}

ファイル: wire_test.go(変えない。D1〜D8)

wire_test.go(246 行)
package main

import (
	"context"
	"errors"
	"fmt"
	"io"
	"log/slog"
	"net/http"
	"net/http/httptest"
	"strings"
	"testing"
	"time"

	"go.opentelemetry.io/otel/baggage"
	sdkmetric "go.opentelemetry.io/otel/sdk/metric"
	"go.opentelemetry.io/otel/sdk/metric/metricdata"
	"go.opentelemetry.io/otel/sdk/trace/tracetest"
)

// 上流(ロードバランサの先の BFF)から来る traceparent。W3C Trace Context の形: 版-trace_id-親span_id-flags。
// trace_id の下位 8 バイトを選んで、TraceIDRatioBased(0.5) の判定を固定している(sampling.go 73 行: 下位 8 バイト >> 1 を比べる)。
const (
	upTraceSampled   = "4bf92f3577b34da6ffffffffffffffff" // 上流は記録した(flags=01)。比率だけなら「捨てる」側
	upTraceUnsampled = "4bf92f3577b34da60000000000000001" // 上流は捨てた(flags=00)。比率だけなら「拾う」側
	upParent         = "00f067aa0ba902b7"
)

// newRigRatio は Day 072 の rig と同じ受け皿で、TracerProvider だけ NewTracerProvider(ratio) にしたもの。
func newRigRatio(ratio float64) *rig {
	g := &rig{buf: &lockedBuf{}, sr: tracetest.NewSpanRecorder(), rd: sdkmetric.NewManualReader()}
	g.tp = NewTracerProvider(g.sr, ratio)
	g.mp = sdkmetric.NewMeterProvider(sdkmetric.WithReader(g.rd))
	g.log = slog.New(NewLogHandler(slog.NewJSONHandler(g.buf, nil)))
	return g
}

func routeByPath(r *http.Request) string { return r.Method + " " + r.URL.Path }

func get(h http.Handler, path string, hdr map[string]string) {
	r := httptest.NewRequest("GET", path, nil)
	r.Header.Set("X-User", "alice")
	for k, v := range hdr {
		r.Header.Set(k, v)
	}
	h.ServeHTTP(httptest.NewRecorder(), r)
}

// D1: 上流が記録したトレースは、続きとして記録する(同じ trace_id・親は上流の span)。
func TestD1_ContinueSampledParent(t *testing.T) {
	g := newRigRatio(0.5)
	get(Stack(okHandler, g.log, g.tp, g.mp, route), "/export",
		map[string]string{"traceparent": "00-" + upTraceSampled + "-" + upParent + "-01"})
	spans, lines := g.sr.Ended(), g.buf.lines(t)
	if len(spans) != 1 {
		t.Fatalf("span %d 本; want 1(上流が記録したのに捨てた)", len(spans))
	}
	s := spans[0]
	if s.SpanContext().TraceID().String() != upTraceSampled || s.Parent().SpanID().String() != upParent || !s.Parent().IsRemote() {
		t.Fatalf("trace=%s parent=%s remote=%v; want %s の続き", s.SpanContext().TraceID(), s.Parent().SpanID(), s.Parent().IsRemote(), upTraceSampled)
	}
	if len(lines) != 1 || lines[0]["trace_id"] != upTraceSampled {
		t.Fatalf("log trace_id=%v; want %s", lines[0]["trace_id"], upTraceSampled)
	}
}

// D2: 上流が捨てたトレースは記録しない。それでもログの trace_id は上流と同じ(ログ同士はつながる)。exemplar は付かない。
func TestD2_RespectUnsampledParent(t *testing.T) {
	g := newRigRatio(0.5)
	get(Stack(okHandler, g.log, g.tp, g.mp, route), "/export",
		map[string]string{"traceparent": "00-" + upTraceUnsampled + "-" + upParent + "-00"})
	spans, lines, pts := g.sr.Ended(), g.buf.lines(t), g.points(t)
	if len(spans) != 0 {
		t.Fatalf("span %d 本; want 0(上流が捨てたのに記録した)", len(spans))
	}
	if len(lines) != 1 || lines[0]["trace_id"] != upTraceUnsampled {
		t.Fatalf("log trace_id=%v; want %s", lines[0]["trace_id"], upTraceUnsampled)
	}
	if len(pts) != 1 || len(pts[0].exTID) != 0 {
		t.Fatalf("points=%+v; want 1 点・exemplar なし", pts)
	}
}

// D3: traceparent が無ければ新しい root(基準線。比率 1 なら必ず記録)。
func TestD3_NewRootWithoutParent(t *testing.T) {
	g := newRigRatio(1)
	get(Stack(okHandler, g.log, g.tp, g.mp, route), "/export", nil)
	spans := g.sr.Ended()
	if len(spans) != 1 || spans[0].Parent().IsValid() {
		t.Fatalf("spans=%d", len(spans))
	}
}

// D4: baggage ヘッダは ctx に入れない(外の利用者が任意の鍵を入れられる。今日は TraceContext だけを読む)。
func TestD4_IgnoreBaggage(t *testing.T) {
	g := newRigRatio(1)
	var n int = -1
	h := Stack(func(w http.ResponseWriter, r *http.Request) error {
		n = baggage.FromContext(r.Context()).Len()
		return nil
	}, g.log, g.tp, g.mp, route)
	get(h, "/export", map[string]string{
		"traceparent": "00-" + upTraceSampled + "-" + upParent + "-01",
		"baggage":     "role=admin,tenant=other",
	})
	if n != 0 {
		t.Fatalf("baggage の要素 %d 個が ctx に入った", n)
	}
}

// D5: WithGroup の後でも trace_id・span_id・request_id は最上位。グループの中には入らない。
func TestD5_KeysStayTopLevelAfterGroup(t *testing.T) {
	g := newRigRatio(1)
	jl := g.log.With("svc", "export").WithGroup("job").With("k", "v")
	h := Stack(func(w http.ResponseWriter, r *http.Request) error {
		jl.InfoContext(r.Context(), "rows", "n", 2)
		return nil
	}, g.log, g.tp, g.mp, route)
	get(h, "/export", nil)
	lines := g.buf.lines(t)
	if len(lines) != 2 {
		t.Fatalf("lines=%d", len(lines))
	}
	l, edge := lines[0], lines[1]
	job, _ := l["job"].(map[string]any)
	if l["trace_id"] == nil || l["trace_id"] != edge["trace_id"] || l["span_id"] != edge["span_id"] ||
		l["request_id"] != edge["request_id"] || l["svc"] != "export" {
		t.Errorf("最上位: trace_id=%v span_id=%v request_id=%v svc=%v; Edge は %v %v %v",
			l["trace_id"], l["span_id"], l["request_id"], l["svc"], edge["trace_id"], edge["span_id"], edge["request_id"])
	}
	if job == nil || job["k"] != "v" || job["n"] != float64(2) || job["trace_id"] != nil || job["request_id"] != nil {
		t.Errorf("job=%v; want {k:v n:2} だけ", job)
	}
}

// D6: 応答の後に走る監査も、同じ trace_id・request_id で成功する(実サーバー。ServeHTTP が戻ると r.Context() は cancel される)。
func TestD6_AuditAfterResponse(t *testing.T) {
	g := newRigRatio(1)
	a := &Auditor{Log: g.log, Delay: 30 * time.Millisecond, Timeout: time.Second}
	srv := httptest.NewServer(Stack(Export(a), g.log, g.tp, g.mp, route))
	req, _ := http.NewRequest("GET", srv.URL+"/export", nil)
	req.Header.Set("X-User", "alice")
	resp, err := http.DefaultClient.Do(req)
	if err != nil {
		t.Fatal(err)
	}
	io.ReadAll(resp.Body)
	resp.Body.Close()
	a.Wait()
	srv.Close()
	var edge, audit map[string]any
	for _, l := range g.buf.lines(t) {
		switch l["msg"] {
		case "request":
			edge = l
		default:
			audit = l
		}
	}
	if edge == nil || audit == nil {
		t.Fatalf("edge=%v audit=%v", edge, audit)
	}
	if audit["msg"] != "audit" || audit["err"] != nil {
		t.Errorf("audit msg=%v err=%v; want 成功", audit["msg"], audit["err"])
	}
	if audit["trace_id"] == nil || audit["trace_id"] != edge["trace_id"] || audit["request_id"] != edge["request_id"] {
		t.Errorf("audit trace_id=%v request_id=%v; Edge は %v %v", audit["trace_id"], audit["request_id"], edge["trace_id"], edge["request_id"])
	}
}

// D7: 監査にも上限がある。cancel を外しても、監査ストアが詰まれば Timeout で諦める(実サーバー)。
func TestD7_AuditHasOwnDeadline(t *testing.T) {
	g := newRigRatio(1)
	a := &Auditor{Log: g.log, Delay: 500 * time.Millisecond, Timeout: 20 * time.Millisecond}
	srv := httptest.NewServer(Stack(Export(a), g.log, g.tp, g.mp, route))
	resp, err := http.Get(srv.URL + "/export")
	if err != nil {
		t.Fatal(err)
	}
	io.ReadAll(resp.Body)
	resp.Body.Close()
	start := time.Now()
	a.Wait()
	srv.Close()
	var audit map[string]any
	for _, l := range g.buf.lines(t) {
		if l["msg"] != "request" {
			audit = l
		}
	}
	if audit == nil || audit["msg"] != "audit failed" || !strings.Contains(fmt.Sprint(audit["err"]), "deadline exceeded") || time.Since(start) > 300*time.Millisecond {
		t.Fatalf("audit=%v(待ち %v); want deadline exceeded で早く諦める", audit, time.Since(start))
	}
}

// D8: 探針(/healthz・/readyz)は span もメトリクスも作らず、SLI に入らない。/readyz の失敗だけはログに残す。
func TestD8_ProbesOutOfSLI(t *testing.T) {
	g := newRigRatio(1)
	h := Stack(func(w http.ResponseWriter, r *http.Request) error {
		switch r.URL.Path {
		case "/healthz":
			io.WriteString(w, "ok")
			return nil
		case "/readyz":
			return &StatusError{Code: 503, Msg: "not ready", Err: errors.New("warming up")}
		}
		if r.Header.Get("X-Fail") != "" {
			return errors.New("pq: connection refused")
		}
		io.WriteString(w, "ok")
		return nil
	}, g.log, g.tp, g.mp, routeByPath)
	for i := 0; i < 100; i++ {
		get(h, "/healthz", nil) // kubelet の liveness(10 秒ごと)の代役
	}
	for i := 0; i < 20; i++ {
		get(h, "/readyz", nil) // 起動直後の readiness 失敗
	}
	for i := 0; i < 9; i++ {
		get(h, "/export", nil)
	}
	get(h, "/export", map[string]string{"X-Fail": "1"})

	var rm metricdata.ResourceMetrics
	g.rd.Collect(context.Background(), &rm)
	routes := map[string]bool{}
	for _, p := range g.points(t) {
		routes[p.attrs["http.route"]] = true
	}
	lines := g.buf.lines(t)
	nReady := 0
	for _, l := range lines {
		if l["route"] == "GET /readyz" {
			nReady++
		}
	}
	if got := SLIFrom(rm); got != 0.9 || len(routes) != 1 || !routes["GET /export"] {
		t.Errorf("SLI=%v routes=%v; want 0.9・GET /export だけ", got, routes)
	}
	if n := len(g.sr.Ended()); n != 10 {
		t.Errorf("span %d 本; want 10(/export だけ)", n)
	}
	if len(lines) != 30 || nReady != 20 {
		t.Errorf("ログ %d 行(readyz %d); want 30(export 10+readyz の失敗 20)", len(lines), nReady)
	}
}

💡 ヒント

ヒント1(方向性)

落ちるテストは 6 本ですが、バグは 5 つです。D1・D2 は 2 つのバグに同時に落とされています。落ち方の文言で見分けてください。「ログの trace_id が上流と違う」と「上流が捨てたのに span が 1 本ある」は、別の原因です。

ヒント2(アプローチ)
  • D1・D2: otelhttp はヘッダを誰に読ませているか(config.go 55 行)。テストは otel.SetTextMapPropagator を呼んでいません。本番の main で呼んでいても、テストや別のバイナリでは呼ばれません
  • D1・D2 の残り: TraceIDRatioBased は親を見ますか(sampling.go 71〜74 行)。SDK の既定(provider.go 520 行)は何で包んでいますか
  • D5: WithGroup の後で Record.AddAttrs した属性は、どこに入りますか(handler.go 81〜88 行の説明)。グループの外に出すには、「グループを開く前の Handler」が要ります
  • D6・D7: r.Context() が cancel されるのはいつですか(request.go 356 行)。値は残して cancel だけ外す関数が context にあります。外すと期限も消えます
  • D8: 探針かどうかを、Filter はパスで、Edge は……見ていますか。2 か所が同じ 1 つの関数を見るようにします
ヒント3(コード骨格)
// B1: 大域に頼らず明示する。Baggage は入れない(D4)
otelhttp.WithPropagators(propagation.TraceContext{}),

// B2: 親があれば親に従う
sdktrace.WithSampler(sdktrace.ParentBased(sdktrace.TraceIDRatioBased(ratio)))

// B3: グループ以降の手順を覚えておき、最上位に鍵を足した root から積み直す
type LogHandler struct {
	root   slog.Handler                      // グループの外
	cur    slog.Handler                      // 全部適用済み
	replay []func(slog.Handler) slog.Handler // 最初の WithGroup 以降
}

// B4: 値は残し cancel を外す。期限は Auditor が自分で持つ
a.Go(context.WithoutCancel(r.Context()), …)

// B5: Filter と Edge が同じ 1 つを見る
func IsProbe(route string) bool { … }

✅ 模範解答

5 つのバグと直し方

#場所バグ起きること(実測)直し方
B1Tracedpropagator を指定せず、大域(未設定=何もしない)に任せた上流の traceparent を読まず、毎回新しい root。ログの trace_id が上流と一致しない(D2: log trace_id=0976a881…; want 4bf92f35…0001)otelhttp.WithPropagators(propagation.TraceContext{}) を明示
B2NewTracerProviderTraceIDRatioBased(ratio) を裸で使った上流の判断を無視。比率 0.1 で、上流が記録した 2,000 件のうち記録 204 件(10.2%)、上流が捨てた 2,000 件のうち記録 190 件(9.5%)=親の無い spanParentBased(TraceIDRatioBased(ratio))
B3LogHandler.WithGroup内側の WithGroup を包み直すだけ(Day 072 のまま)trace_id・span_id・request_id が job の中に入る(D5: job=map[k:v n:2 request_id:… span_id:… trace_id:…])。最上位の trace_id で検索しても出てこないグループ以降の手順を覚えておき、遅い道では「最上位に鍵を足した root」から積み直す
B4Exportgo a.Go(r.Context(), …)ServeHTTP が戻った瞬間に cancel。監査は応答を読み終えてから 0.16 ms 以内に audit failed: context canceled(D6・D7)context.WithoutCancel(r.Context())。期限は Auditor.Timeout で別に持つ
B5Traced・EdgeFilter はパス /healthz だけ、Edge は探針を知らない/healthz 100 件・/readyz(503)20 件・/export 10 件(うち失敗 1)で、SLI が 0.838(正しくは 0.9)。span 30 本(/readyz 20 本が混入)、ログ 130 行IsProbe(route) を 1 つ作り、Filter と Edge の両方が見る。探針はメトリクスに入れず、ログは失敗だけ

edge.go(修正版・272 行)

package main

import (
	"context"
	"crypto/rand"
	"encoding/hex"
	"log/slog"
	"net/http"
	"runtime/debug"
	"slices"
	"strconv"
	"time"

	"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/codes"
	"go.opentelemetry.io/otel/metric"
	metricnoop "go.opentelemetry.io/otel/metric/noop"
	"go.opentelemetry.io/otel/propagation"
	"go.opentelemetry.io/otel/sdk/metric/metricdata"
	sdktrace "go.opentelemetry.io/otel/sdk/trace"
	"go.opentelemetry.io/otel/semconv/v1.43.0/httpconv"
	"go.opentelemetry.io/otel/trace"
)

// ---- ログ: ctx にある trace_id・span_id・request_id を、どの 1 行にも「最上位に」足す ----

// LogHandler は包んだ slog.Handler の前に 1 段入る。
// 修正 B3: WithGroup の後でも trace_id がグループの中に入らないよう、
// グループ以降の手順(replay)を覚えておき、Handle で「最上位に鍵を足した root」から積み直す。
type LogHandler struct {
	root   slog.Handler                      // グループの外(最上位)。最初の WithGroup より前の WithAttrs はここに焼く
	cur    slog.Handler                      // すべて適用済み(Enabled と速い道で使う)
	replay []func(slog.Handler) slog.Handler // 最初の WithGroup 以降の手順
}

func NewLogHandler(h slog.Handler) *LogHandler { return &LogHandler{root: h, cur: h} }

func (h *LogHandler) Enabled(ctx context.Context, l slog.Level) bool { return h.cur.Enabled(ctx, l) }

// keysInto は ctx の鍵を buf に足して返す。呼び出し側の配列を使い、速い道で割り当てを増やさない。
func keysInto(ctx context.Context, buf []slog.Attr) []slog.Attr {
	if sc := trace.SpanContextFromContext(ctx); sc.IsValid() {
		buf = append(buf, slog.String("trace_id", sc.TraceID().String()), slog.String("span_id", sc.SpanID().String()))
	}
	if o := outcomeFrom(ctx); o != nil {
		buf = append(buf, slog.String("request_id", o.RequestID))
	}
	return buf
}

func (h *LogHandler) Handle(ctx context.Context, rec slog.Record) error {
	var arr [3]slog.Attr
	ks := keysInto(ctx, arr[:0])
	if len(h.replay) == 0 || len(ks) == 0 { // 速い道: グループが無ければ Record に足すだけで最上位に出る
		rec.AddAttrs(ks...)
		return h.cur.Handle(ctx, rec)
	}
	hh := h.root.WithAttrs(slices.Clone(ks)) // 遅い道: 最上位に鍵を足してからグループを積み直す(1 行ごとに割り当てが出る)
	for _, f := range h.replay {
		hh = f(hh)
	}
	return hh.Handle(ctx, rec)
}

func (h *LogHandler) WithAttrs(as []slog.Attr) slog.Handler {
	if len(as) == 0 {
		return h
	}
	if len(h.replay) == 0 {
		r := h.root.WithAttrs(as)
		return &LogHandler{root: r, cur: r}
	}
	as = slices.Clone(as)
	return &LogHandler{root: h.root, cur: h.cur.WithAttrs(as),
		replay: append(slices.Clip(h.replay), func(x slog.Handler) slog.Handler { return x.WithAttrs(as) })}
}

func (h *LogHandler) WithGroup(name string) slog.Handler {
	if name == "" {
		return h
	}
	return &LogHandler{root: h.root, cur: h.cur.WithGroup(name),
		replay: append(slices.Clip(h.replay), func(x slog.Handler) slog.Handler { return x.WithGroup(name) })}
}

// requestID は来た X-Request-Id を、短く・安全な文字だけなら引き継ぐ。それ以外は作り直す。
func requestID(r *http.Request) string {
	if v := r.Header.Get("X-Request-Id"); validRequestID(v) {
		return v
	}
	var b [8]byte
	rand.Read(b[:])
	return hex.EncodeToString(b[:])
}

func validRequestID(s string) bool {
	if len(s) == 0 || len(s) > 64 {
		return false
	}
	for i := 0; i < len(s); i++ {
		c := s[i]
		if !('a' <= c && c <= 'z' || 'A' <= c && c <= 'Z' || '0' <= c && c <= '9' || c == '-' || c == '_' || c == '.') {
			return false
		}
	}
	return true
}

// ---- メトリクスとトレースの属性(OTel HTTP semconv に合わせる) ----

const AbortedErrorType = "aborted"

func errorTypeOf(status int, aborted bool) string {
	switch {
	case aborted:
		return AbortedErrorType
	case status >= 500:
		return strconv.Itoa(status)
	}
	return ""
}

func methodOf(m string) httpconv.RequestMethodAttr {
	switch m {
	case "GET", "HEAD", "POST", "PUT", "DELETE", "CONNECT", "OPTIONS", "TRACE", "PATCH":
		return httpconv.RequestMethodAttr(m)
	}
	return httpconv.RequestMethodOther
}

// IsProbe は「利用者の要求ではない」ルート。修正 B5: Traced の Filter と Edge が同じこの 1 つを見る。
// 判定はパスでなくルート(routeOf の結果)で行う。
func IsProbe(route string) bool { return route == "GET /healthz" || route == "GET /readyz" }

// Edge は Day 072 の Edge。修正 B5: 探針(probe)はメトリクスに入れず、ログは失敗のときだけ。
func Edge(log *slog.Logger, mp metric.MeterProvider, routeOf func(*http.Request) string) func(http.Handler) http.Handler {
	dur, err := httpconv.NewServerRequestDuration(mp.Meter("d73/edge"))
	if err != nil {
		panic(err)
	}
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			start := time.Now()
			o := &Outcome{RequestID: requestID(r)}
			w.Header().Set("X-Request-Id", o.RequestID)
			ow := &obsWriter{ResponseWriter: w}
			r = r.WithContext(context.WithValue(r.Context(), outcomeKey{}, o))
			defer func() {
				p := recover()
				aborted := p != nil
				if aborted && p != http.ErrAbortHandler && o.Panic == nil {
					o.Panic, o.Stack = p, debug.Stack()
				}
				status := ow.status
				if status == 0 && !aborted {
					status = http.StatusOK
					if r.Context().Err() != nil {
						status = StatusClientClosed
						ow.WriteHeader(status)
					}
				}
				class, et := classOf(status, aborted), errorTypeOf(status, aborted)
				d, route := time.Since(start), routeOf(r)
				probe := IsProbe(route)

				if !probe {
					attrs := make([]attribute.KeyValue, 0, 3)
					attrs = append(attrs, dur.AttrRoute(route))
					if status != 0 {
						attrs = append(attrs, dur.AttrResponseStatusCode(status))
					}
					if et != "" {
						attrs = append(attrs, dur.AttrErrorType(httpconv.ErrorTypeAttr(et)))
					}
					scheme := "http"
					if r.TLS != nil {
						scheme = "https"
					}
					dur.Record(r.Context(), d.Seconds(), methodOf(r.Method), scheme, attrs...)
				}

				span := trace.SpanFromContext(r.Context())
				if et != "" {
					span.SetAttributes(attribute.String("error.type", et))
				}
				if aborted {
					span.SetStatus(codes.Error, "aborted")
					if status != 0 {
						span.SetAttributes(attribute.Int("http.response.status_code", status))
					}
				}

				level := slog.LevelInfo
				if class == ClassServerError || class == ClassAborted {
					level = slog.LevelError
				}
				if !probe || level == slog.LevelError {
					la := make([]slog.Attr, 0, 9)
					la = append(la,
						slog.String("method", r.Method), slog.String("route", route),
						slog.Int("status", status), slog.String("class", class),
						slog.Int64("dur_us", d.Microseconds()), slog.String("user", o.User))
					if o.Err != nil {
						la = append(la, slog.String("err", o.Err.Error()))
					}
					if o.Panic != nil {
						la = append(la, slog.Any("panic", o.Panic), slog.String("stack", string(o.Stack)))
					}
					log.LogAttrs(r.Context(), level, "request", la...)
				}
				if p != nil {
					panic(p)
				}
			}()
			next.ServeHTTP(ow, r)
		})
	}
}

// Propagator は外から来る traceparent だけを読む。修正 B1: 大域(otel.GetTextMapPropagator)に頼らず明示する。
// Baggage は入れない(外の利用者が任意の鍵と値を ctx に入れられるため)。
var Propagator propagation.TextMapPropagator = propagation.TraceContext{}

// Traced は otelhttp をトレースだけに使って h を包む。
func Traced(h http.Handler, tp trace.TracerProvider, routeOf func(*http.Request) string) http.Handler {
	return otelhttp.NewHandler(h, "http.server",
		otelhttp.WithTracerProvider(tp),
		otelhttp.WithMeterProvider(metricnoop.NewMeterProvider()),
		otelhttp.WithPropagators(Propagator),
		otelhttp.WithFilter(func(r *http.Request) bool { return !IsProbe(routeOf(r)) }),
		otelhttp.WithSpanNameFormatter(func(_ string, r *http.Request) string { return routeOf(r) }))
}

// NewTracerProvider は自分で始めるトレースだけを ratio で間引く。
// 修正 B2: 親(上流)の判断があればそれに従う(ParentBased)。
func NewTracerProvider(sp sdktrace.SpanProcessor, ratio float64) *sdktrace.TracerProvider {
	return sdktrace.NewTracerProvider(
		sdktrace.WithSpanProcessor(sp),
		sdktrace.WithSampler(sdktrace.ParentBased(sdktrace.TraceIDRatioBased(ratio))))
}

// Stack は otelhttp(トレースだけ)→ Edge → Identify → Recover → Adapt の順に積む(Day 072 と同じ)。
func Stack(h HandlerE, log *slog.Logger, tp trace.TracerProvider, mp metric.MeterProvider, routeOf func(*http.Request) string) http.Handler {
	return Traced(Edge(log, mp, routeOf)(Identify(Recover(PanicInto)(Adapt(h, ErrInto)))), tp, routeOf)
}

// SLIFrom は Day 072 と同じ。
func SLIFrom(rm metricdata.ResourceMetrics) float64 {
	var valid, bad uint64
	for _, sm := range rm.ScopeMetrics {
		for _, m := range sm.Metrics {
			h, ok := m.Data.(metricdata.Histogram[float64])
			if m.Name != "http.server.request.duration" || !ok {
				continue
			}
			for _, dp := range h.DataPoints {
				if v, ok := dp.Attributes.Value("http.response.status_code"); ok && v.AsInt64() == StatusClientClosed {
					continue
				}
				valid += dp.Count
				if dp.Attributes.HasValue("error.type") {
					bad += dp.Count
				}
			}
		}
	}
	if valid == 0 {
		return 1
	}
	return float64(valid-bad) / float64(valid)
}

app.go(修正版・50 行)

package main

import (
	"context"
	"io"
	"log/slog"
	"net/http"
	"sync"
	"time"
)

// Auditor は「誰が何を書き出したか」を監査ログに残す。書き込みは遅い(外部の監査ストアの代役)ので、
// 応答を待たせないよう別の goroutine で行う。
type Auditor struct {
	Log     *slog.Logger
	Delay   time.Duration // 監査ストアへの書き込みにかかる時間
	Timeout time.Duration // 監査 1 件の上限。要求の ctx から cancel を外すので、期限は自分で持つ
	wg      sync.WaitGroup
}

// Go は監査の書き込みを別 goroutine で始める。ctx は書き込みの期限と、ログの鍵(trace_id・request_id)を運ぶ。
func (a *Auditor) Go(ctx context.Context, user, what string) {
	a.wg.Add(1)
	go func() {
		defer a.wg.Done()
		ctx, cancel := context.WithTimeout(ctx, a.Timeout)
		defer cancel()
		select {
		case <-time.After(a.Delay):
		case <-ctx.Done():
			a.Log.ErrorContext(ctx, "audit failed", "user", user, "what", what, "err", ctx.Err().Error())
			return
		}
		a.Log.InfoContext(ctx, "audit", "user", user, "what", what)
	}()
}

// Wait はテストと停止処理のために、始めた書き込みがすべて終わるのを待つ。
func (a *Auditor) Wait() { a.wg.Wait() }

// Export は /export のハンドラ。CSV を返し、監査を残す。
// 修正 B4: r.Context() は ServeHTTP が戻ると cancel される(request.go 356 行)。
// 値(span・袋)は残したまま cancel だけ外す context.WithoutCancel(Go 1.21+)を渡す。
func Export(a *Auditor) HandlerE {
	return func(w http.ResponseWriter, r *http.Request) error {
		a.Go(context.WithoutCancel(r.Context()), r.Header.Get("X-User"), "export")
		io.WriteString(w, "id,name\n1,alice\n")
		return nil
	}
}

実行結果(Go 1.27.2、otel v1.45.0・otelhttp v0.70.0、2026-10-13)

$ go test -race -count=1 -v ./... 2>&1 | grep -E '^(---|ok)'
--- PASS: TestO1_OneSemconvPoint (0.01s)
--- PASS: TestO2_SpanFilledEverywhere (0.01s)
--- PASS: TestO3_LogJoinsTrace (0.01s)
--- PASS: TestO4_RequestIDInput (0.00s)
--- PASS: TestO5_ExemplarLinksTrace (0.00s)
--- PASS: TestO6_SLIFromMetrics (0.07s)
--- PASS: TestO7_Concurrent (0.02s)
--- PASS: TestO8_NoRecoverNothingSent (0.00s)
--- PASS: TestO9_ClientView (0.00s)
--- PASS: TestO10_UnknownMethod (0.00s)
--- PASS: TestO11_HandlerLogWithAttrs (0.00s)
--- PASS: TestD1_ContinueSampledParent (0.00s)
--- PASS: TestD2_RespectUnsampledParent (0.00s)
--- PASS: TestD3_NewRootWithoutParent (0.00s)
--- PASS: TestD4_IgnoreBaggage (0.00s)
--- PASS: TestD5_KeysStayTopLevelAfterGroup (0.00s)
--- PASS: TestD6_AuditAfterResponse (0.03s)
--- PASS: TestD7_AuditHasOwnDeadline (0.02s)
--- PASS: TestD8_ProbesOutOfSLI (0.00s)
ok  	d73	1.506s

-count=20 で 20 回流しても 19 本すべて通った(4.9 秒)。

🪜 Step-by-Step 解説

Step 1: 6 本の落ち方を、原因ごとに分ける

バグ入りで落ちるのは D1・D2・D5・D6・D7・D8 の 6 本。Day 072 の O1〜O11 は 1 本も落ちません。昨日のテストは「traceparent が無い・比率 100%・グループなし・同期処理・探針なし」の世界しか見ていなかったからです。

バグを 1 つだけ入れて流すと、どのテストがどのバグを見ているかが分かります(2026-10-13 実測)。

入れたバグ落ちたテスト落ち方の決め手
B1 だけD1, D2D2 の「ログの trace_id が上流と違う」
B2 だけD1, D2D2 の「上流が捨てたのに span が 1 本」
B3 だけD5—
B4 だけD6, D7—
B5 だけD8—
5 つ全部D1, D2, D5, D6, D7, D8—

5 つのうち 4 つを直して 1 つだけ残すと、残したバグの行と同じテストだけが落ちました。今日は、あるバグが別のバグを隠す組み合わせは無かった(Day 067・070 では隠れていた)。その代わり、B1 と B2 は同じテストを同じ名前で落とすので、テスト名だけでは区別できません。

Step 2: B1 —— 大域の既定は「何もしない」

otelhttp は、propagator を指定しないと otel.GetTextMapPropagator() を使います(config.go 55 行)。大域の propagator は、誰かが otel.SetTextMapPropagator(...) を呼ぶまで何もしないものに流れます。つまり traceparent ヘッダは読まれず、毎回新しい root ができます。

本番の main で SetTextMapPropagator を呼んでいれば動きます。でも、テスト・別のバイナリ(バッチ・CLI)・main の呼ぶ順の入れ替えで静かに外れます。今日は大域に頼らず WithPropagators で明示しました。Day 072 の Edge が MeterProvider・TracerProvider を引数で受け取ったのと同じ考え方です。

入れるのは TraceContext だけです。propagation.Baggage{} も足すと(変異 W1)、外の利用者が baggage: role=admin のような任意の鍵を ctx に入れられます。D4 はそれを見張ります。

Step 3: B2 —— 比率の sampler は親を見ない

TraceIDRatioBased は trace_id の下位 8 バイトだけで決めます(sampling.go 73 行)。上流の flags は見ません。

  • 上流が記録したトレース: 自分の span は 10% しか残らない → 上流から見ると「/export の span がほとんど出てこない」
  • 上流が捨てたトレース: 10% を記録する → 親(上流の span)がどこにも無い span ができる

SDK の既定は ParentBased(AlwaysSample())(provider.go 520 行)です。比率を入れるときも ParentBased で包むのが既定の形を壊さない直し方です。D1・D2 は、比率 0.5 の判定が逆になる trace_id(下位 8 バイトが ff…ff と 00…01)を選んで、乱数に頼らず決定的に落ちるようにしています。

B1 が残っていると、B2 を直しても D1・D2 は落ちたままです(新しい root に対して比率が効くだけなので)。直す順は B1 → B2 が分かりやすいです。

Step 4: B3 —— WithGroup の後の AddAttrs はグループの中

slog の約束では、WithGroup("job") の後に足した属性は、行の終わりまで全部 job の中に入ります(handler.go 81〜88 行)。Day 072 の LogHandler は Handle の中で rec.AddAttrs していたので、WithGroup を通ったロガーでは鍵が job.trace_id になりました。

直し方は 3 つ考えました(下の「迷った他案」)。採ったのは「グループを開く前の Handler(root)」を覚えておき、グループがあるときだけ root に鍵を足してから手順を積み直す方法です。

  • 速い道(グループなし。ほとんどの行): Day 072 と同じく rec.AddAttrs。割り当て 48 B・2 allocs のまま(呼び出し側の配列 [3]slog.Attr を使い、最初の版の 288 B・4 allocs から戻した)
  • 遅い道(グループあり): 1 行ごとに WithAttrs・WithGroup をやり直すので 1,128 B・14 allocs

Step 5: B4 —— r.Context() は「応答が終わるまで」の ctx

r.Context() は ServeHTTP が戻ると cancel されます(request.go 356 行、server.go 2159 行)。監査の goroutine は応答の後も動くので、30 ms 待つ前に context canceled で落ちました(実測で、応答を読み終えてから 0.16 ms 以内)。

context.Background() に替えると落ちなくなりますが、trace_id と request_id も消えます(変異 W2 で D6 が落ちる)。context.WithoutCancel(r.Context()) は値を残して cancel だけを外します。ただし期限も消えるので、監査ストアが詰まると goroutine が積み上がります。Auditor.Go の中で context.WithTimeout(ctx, a.Timeout) を掛け直しました(変異 W3 で D7 が落ちる)。

Step 6: B5 —— 「探針か」を 2 か所で別々に決めない

同僚の Filter は r.URL.Path != "/healthz" でした。Edge は探針を知らないので、/healthz の 200 も /readyz の 503 も http.server.request.duration に入ります。SLI は 2 方向に狂います。

  • 平常時: /healthz の 200 が分母を水増し → 実際より高く出る
  • 起動直後・依存先の障害時: /readyz の 503 が失敗に数えられる → 実際より低く出る

直し方は IsProbe(route) を 1 つ作り、Filter と Edge の両方がそれを見ることです。判定はパスでなく routeOf の結果(Day 063 以来の http.route)で行います。Edge は探針のときメトリクスを書かず、ログは失敗(/readyz の 503)だけ残します。

📏 実測(予想と外れた所を含む)

1. 予想の答え合わせ

  • P1(比率だけの sampler): 比率 0.1、ランダムな trace_id 2,000 件ずつ。上流 01(記録した)→ 自分も記録 204 件(10.2%)、上流 00(捨てた)→ 記録 190 件(9.5%)。ParentBased にすると 2,000 件(100%) と 0 件(0%)
  • P2(WithGroup の直しの費用): グループあり 1 行で 48 B・2 allocs → 1,128 B・14 allocs。グループなしは 48 B・2 allocs のまま(最初の版は 288 B・4 allocs に増えていた。鍵を可変長スライスで集めていたため。[3]slog.Attr の配列を渡して戻した)。時間はグループなし 510〜530 ns、あり 910〜920 ns だが、ロードアベレージ 17.5 の中で測ったので比較に使わない
  • P3(監査が落ちるまで): 応答を読み終えてから 0.16 ms 以内(D7 の失敗表示の「待ち 160.583µs」)。30 ms の監査は 1 件も成功しない

2. 比率サンプリングでの exemplar(Day 072 の「扱わなかった範囲」の続き)

比率 0.1・ParentBased・親なしで、失敗(500)1 件だけの rig を 2,000 個作った。

件数割合
失敗の点に exemplar が付いた1899.4%
Edge のログに trace_id が載った2,000100%

記録されなかった span も trace_id と span_id は持つ(SDK は記録しない span にも ID を付ける)ので、ログ同士は trace_id でつながります。でも exemplar は IsSampled() だけを見る(filter.go 23 行)ので、失敗の 9 割で「グラフの点からトレースへ飛ぶ」道が消えます。D2 は「上流が捨てた要求には exemplar が付かない」ことを固定しています。

3. 直し方の変異(間違った直し方を、どのテストが止めるか)

変異内容検出したテスト
W1propagator に Baggage も足すD4
W2監査に context.Background() を渡すD6
W3WithoutCancel の後に期限を掛けないD7
W4Edge だけ直し、Filter はパス /healthz のままD8
W5WithGroup で LogHandler を外して素の Handler を返すD5
W6探針は失敗もログに残さないD8
W7外からの traceparent を信じず WithPublicEndpointFn(常に true)D1, D2
W8速い道だけにする(グループがあっても AddAttrs)D5
W9Filter だけ直し、Edge は探針を知らないD8

9 通りすべて検出。D3(親なしで新しい root)と D4(baggage を入れない)はバグ入りでも通る基準線で、D4 は W1 だけを止めるためにある。

4. 探針が SLI をどれだけ動かすか

D8 の配分(仮定): /healthz 200 が 100 件、/readyz 503 が 20 件、/export 成功 9 件・失敗 1 件。

SLIspanログ
バグ入り(100 + 9) / 130 = 0.83830 本130 行
修正後9 / 10 = 0.90010 本30 行

本番の規模に置き直すと(導出。前提は仮定): kubelet の既定の間隔 10 秒(記憶)で liveness と readiness を叩くと、1 Pod あたり 2 × 8,640 = 17,280 件/日。3 Pod で 51,840 件/日。利用者の要求が 5 rps(432,000 件/日)で本当の可用性が 99.5% なら、探針込みの SLI は (429,840 + 51,840) / 483,840 = 99.55%。誤差予算の消費が 約 1 割少なく見えます。

⚖️ 迷った他案と採らなかった理由

論点採った案迷った他案と採らなかった理由前提が変わったら
propagator の置き場所otelhttp.WithPropagators で明示main で otel.SetTextMapPropagator: OTel の入門どおりで、外向きの HTTP クライアント(otelhttp の Transport)にも効く。ただしテストや別のバイナリで呼び忘れると静かに外れる(今日の B1)外向きの呼び出しが増えたら、大域にも同じ値を設定し、「大域と Traced が同じ propagator か」を起動時に確かめる
何を propagate するかTraceContext だけTraceContext+Baggage: 上流の tenant などを使える。だが外の利用者が任意の鍵を ctx に入れられる(W1)上流が社内の BFF だけで、Edge の手前で baggage ヘッダを消していると確かめられたら、Baggage を足してよい
外から来た trace を信じるか信じて親にするWithPublicEndpointFn で新しい root+link: 外の利用者が trace_id を選べなくなる。だが上流 BFF とのトレースが切れる(W7)インターネットから直接来る入口(BFF を通らない)を足したら、その入口だけ public にする
samplerParentBased(TraceIDRatioBased(r))上流に関係なく 10%: 上流のトレースが穴あきになる(B2)。OTel の新しい確率サンプリング(tracestate の th): サービス間で同じ判断を共有できるが、今回は読んでいない上流が sampled を立てすぎて記録量が予算を超えたら、ParentBased の WithRemoteParentSampled に比率を入れる案を測る
WithGroup の扱いroot から積み直す(遅い道は 1,128 B・14 allocs)グループの中に入るのを受け入れる: 費用 0。だがログ検索が trace_id と job.trace_id の 2 通りになる。WithGroup を使わない約束(lint で禁止): 費用 0。だが外部ライブラリが渡された logger に WithGroup することは止められないグループ付きの行が全体の大半になったら、Handler を自作(JSON を直接書く)して鍵を先に書く方を測る
監査の ctxWithoutCancel+監査自身の Timeoutcontext.Background(): trace_id・request_id が消える(W2)。応答の前に同期で書く: 監査ストアの遅さがそのまま応答時間になる監査を失ってはならない(法令・契約の要件)なら、goroutine でなく永続キュー(送信箱)に書いてから応答する。今日の goroutine はプロセスが落ちると消える
探針の判定ルートで 1 か所(IsProbe)パスで判定: /healthz/ や /readyz の足し忘れが起きる(B5)。探針を別ポート・別の mux に出す: いちばん確実だが、今日のテストの範囲(1 つの Stack)を超えるPod の設定を変えられるなら、探針は別ポートに出し、Edge を通さない

🧭 設計思想・なぜこう書くのか

  • 大域より明示: Go の OTel は大域(otel.SetTracerProvider など)を用意していますが、今日の B1 は「大域に頼った結果、テストでは何も起きない」形でした。Day 072 で Provider を引数で渡したのと同じく、propagator も引数(オプション)で渡すと、テストと本番が同じ道を通ります
  • ctx は値と cancel の 2 つを運ぶ: Go の ctx は「この要求の値」と「この要求の寿命」を 1 つで運びます。要求より長生きする処理(監査)には、値だけを渡す必要があります。WithoutCancel はそのための関数で、Go 1.21 で入りました
  • 1 つの判定は 1 か所で: Day 071 は「記録は Edge が 1 回だけ」、今日は「探針の判定は IsProbe 1 つだけ」。同じ判定を 2 か所に書くと、片方だけ直されます

🌐 他言語との比較

言語・FW上流の trace を引き継ぐ既定要求より長生きする処理への引き継ぎ今日の Go との違い
Go(今日)otelhttp は大域の propagator。大域の既定は何もしないcontext.WithoutCancel で値だけ渡す手で渡す。渡し方を間違えると静かに消える
Java(OTel Java agent)エージェントが W3C TraceContext と Baggage を既定で読む(記憶)Context.current().wrap(runnable) で包む(記憶)既定で Baggage も入る点が今日の判断と逆
Python(opentelemetry-sdk)環境変数 OTEL_PROPAGATORS の既定は tracecontext,baggage(記憶)contextvars はスレッドをまたぐと手で copy が要る(記憶)既定が「読む」側
Node(@opentelemetry/sdk-node)既定で W3C TraceContext と Baggage(記憶)AsyncLocalStorage で非同期処理に自動で伝わる(記憶)cancel の概念が ctx と別(AbortSignal)

(Java・Python・Node の行は今回ソースも実行も確認していない。Go は既定が「何もしない」で、他は「読む」が既定という違いが、B1 が Go で起きやすい理由の候補だが、確かめていない)

🏭 実務での使いどころ

  • otelhttp を入れた PR のレビュー: WithPropagators が無ければ、main の SetTextMapPropagator を探す。無ければ B1。あっても、テストが本番と同じ道を通っているかを見る
  • sampler を変える PR: TraceIDRatioBased が ParentBased に包まれているかを見る。上流チームからの「span が穴あき」「親の無い span」の報告は B2 の典型
  • ログ検索で出てこない行がある: WithGroup を使うライブラリ(DB ドライバ・HTTP クライアントの slog 対応)に logger を渡していないかを見る
  • go func() に r.Context() を渡しているコード: ほぼ全部が B4。WithoutCancel+自前の期限にする。失ってはならない処理なら goroutine をやめて送信箱にする
  • SLO のダッシュボード: http.route に /healthz・/readyz・/metrics が出ていたら B5

⚠️ よくある誤解・ミス

誤解・ミスなぜ起こるか正しい理解
otelhttp を入れれば上流の trace は引き継がれる計装ライブラリが全部やると思うGo では propagator を設定しないと読まない(config.go 55 行+大域の既定は何もしない)
比率サンプリングは 10% と書けば 10% になるだけ自分のサービスしか見ていない親を見ない sampler は、上流のトレースに穴を開け、親の無い span を作る
Handle の中で AddAttrs すれば最上位に出るグループの無いロガーでしか試していないWithGroup の後はグループの中に入る。slog の約束どおりの動き
go f(r.Context()) は安全ctx を渡すのが Go の作法だからServeHTTP が戻ると cancel される。値だけ要るなら WithoutCancel
WithoutCancel を使えば終わりcancel の問題が消えるので期限も消える。自分で WithTimeout を掛け直す
探針は Filter で外したから SLI にも入らないトレースとメトリクスを 1 つの部品が出していると思うDay 072 からメトリクスは Edge が書く。Filter はトレースにしか効かない

🚧 扱わなかった範囲と理由

範囲理由
slog.Info(ctx なし)で trace_id が消える件(Day 072 の予告に入れていた)Day 072 の変異 M11 と同じ形(ctx を渡さない)で、今日は ctx の「寿命」の方(B4)を優先した。lint(sloglint の context 規則など)で止める案は未確認
外向きの呼び出し(otelhttp の Transport)で traceparent を送る側今日は受ける側だけ。送る側は大域の propagator を使うので、B1 の直し方(明示)と食い違う可能性がある
OTel の新しい確率サンプリング(tracestate の th・flags の random ビット)trace_context.go 49 行に random フラグの扱いがあるのは見たが、仕様も実装も読んでいない
監査を失わない設計(送信箱・永続キュー)goroutine の監査はプロセスが落ちると消える。今日はテストで「落ちない」だけを確かめた
探針を別ポートに出す構成今日のテストは 1 つの Stack の中。Pod の設定まで含めると範囲を超える
W3C Trace Context の仕様本文・kubelet の既定値今回は取得していない。kubelet の 10 秒は記憶
時間の比較ロードアベレージ 17.5。割り当てだけを根拠にした
Java・Python・Node の行「記憶」と書いた。確認していない

➡️ 次のステップ

  • 発展: 外向きの HTTP クライアントにも同じ propagator を使い、「受けた trace_id で下流を呼ぶ」ことをテストにする。大域と Traced の propagator が食い違ったら起動時に止める
  • 次回予告: 同テーマで「設計・アーキテクチャ」——ここまでの Edge(Day 071〜073)を、別のサービスでも使える部品として切り出すときの API を決める。何を引数にし、何を既定にし、何を利用者に選ばせないか(propagator・sampler・探針・request_id の規則)。10/25 にテーマが進む前の、このテーマのまとめに向けた 1 本

🎯 自己評価(解いた後に記入)

自分の回答(5 つのうち見つけた数 / 落ちたテストとの対応)

P1・P2・P3 の予想と答え合わせ

気づき・メモ