フェーズ: 上級者 (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 監査(応答後に書く)
用語
| 用語 | 意味 |
|---|---|
| traceparent | W3C Trace Context のヘッダ。00-<trace_id 32 桁>-<親 span_id 16 桁>-<flags 2 桁>。flags の 01 は「上流はこのトレースを記録した(sampled)」 |
| propagator | ヘッダと ctx の間で trace の情報を出し入れする部品。Extract(ヘッダ→ctx)と Inject(ctx→ヘッダ) |
| sampler | span を記録するかを決める部品。TraceIDRatioBased(0.1) は trace_id から 10% を選ぶ。ParentBased(x) は親があれば親の判断に従い、親が無いときだけ x に聞く |
| 探針(probe) | Kubernetes の liveness・readiness のように、機械が定期的に叩く /healthz・/readyz。利用者の要求ではない |
context.WithoutCancel | Go 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 の Filter | Filter が 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 の sampler | TraceIDRatioBased は 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 に監査を付けました。
NewTracerProvider(sp, ratio): 本番は 1 日数千万要求なので、トレースは 10% だけ記録したいTracedにWithFilter: kubelet が 10 秒ごとに叩く/healthzの span が多すぎる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.go55 行)。テストはotel.SetTextMapPropagatorを呼んでいません。本番のmainで呼んでいても、テストや別のバイナリでは呼ばれません - D1・D2 の残り:
TraceIDRatioBasedは親を見ますか(sampling.go71〜74 行)。SDK の既定(provider.go520 行)は何で包んでいますか - D5:
WithGroupの後でRecord.AddAttrsした属性は、どこに入りますか(handler.go81〜88 行の説明)。グループの外に出すには、「グループを開く前の Handler」が要ります - D6・D7:
r.Context()が cancel されるのはいつですか(request.go356 行)。値は残して 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 つのバグと直し方
| # | 場所 | バグ | 起きること(実測) | 直し方 |
|---|---|---|---|---|
| B1 | Traced | propagator を指定せず、大域(未設定=何もしない)に任せた | 上流の traceparent を読まず、毎回新しい root。ログの trace_id が上流と一致しない(D2: log trace_id=0976a881…; want 4bf92f35…0001) | otelhttp.WithPropagators(propagation.TraceContext{}) を明示 |
| B2 | NewTracerProvider | TraceIDRatioBased(ratio) を裸で使った | 上流の判断を無視。比率 0.1 で、上流が記録した 2,000 件のうち記録 204 件(10.2%)、上流が捨てた 2,000 件のうち記録 190 件(9.5%)=親の無い span | ParentBased(TraceIDRatioBased(ratio)) |
| B3 | LogHandler.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」から積み直す |
| B4 | Export | go a.Go(r.Context(), …) | ServeHTTP が戻った瞬間に cancel。監査は応答を読み終えてから 0.16 ms 以内に audit failed: context canceled(D6・D7) | context.WithoutCancel(r.Context())。期限は Auditor.Timeout で別に持つ |
| B5 | Traced・Edge | Filter はパス /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, D2 | D2 の「ログの trace_id が上流と違う」 |
| B2 だけ | D1, D2 | D2 の「上流が捨てたのに 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 が付いた | 189 | 9.4% |
| Edge のログに trace_id が載った | 2,000 | 100% |
記録されなかった span も trace_id と span_id は持つ(SDK は記録しない span にも ID を付ける)ので、ログ同士は trace_id でつながります。でも exemplar は IsSampled() だけを見る(filter.go 23 行)ので、失敗の 9 割で「グラフの点からトレースへ飛ぶ」道が消えます。D2 は「上流が捨てた要求には exemplar が付かない」ことを固定しています。
3. 直し方の変異(間違った直し方を、どのテストが止めるか)
| 変異 | 内容 | 検出したテスト |
|---|---|---|
| W1 | propagator に Baggage も足す | D4 |
| W2 | 監査に context.Background() を渡す | D6 |
| W3 | WithoutCancel の後に期限を掛けない | D7 |
| W4 | Edge だけ直し、Filter はパス /healthz のまま | D8 |
| W5 | WithGroup で LogHandler を外して素の Handler を返す | D5 |
| W6 | 探針は失敗もログに残さない | D8 |
| W7 | 外からの traceparent を信じず WithPublicEndpointFn(常に true) | D1, D2 |
| W8 | 速い道だけにする(グループがあっても AddAttrs) | D5 |
| W9 | Filter だけ直し、Edge は探針を知らない | D8 |
9 通りすべて検出。D3(親なしで新しい root)と D4(baggage を入れない)はバグ入りでも通る基準線で、D4 は W1 だけを止めるためにある。
4. 探針が SLI をどれだけ動かすか
D8 の配分(仮定): /healthz 200 が 100 件、/readyz 503 が 20 件、/export 成功 9 件・失敗 1 件。
| SLI | span | ログ | |
|---|---|---|---|
| バグ入り | (100 + 9) / 130 = 0.838 | 30 本 | 130 行 |
| 修正後 | 9 / 10 = 0.900 | 10 本 | 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 にする |
| sampler | ParentBased(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 を直接書く)して鍵を先に書く方を測る |
| 監査の ctx | WithoutCancel+監査自身の Timeout | context.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 回だけ」、今日は「探針の判定は
IsProbe1 つだけ」。同じ判定を 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 本