フェーズ: 上級者 (Phase 3) | 問題タイプ: 実装 | テーマ: ミドルウェア設計パターン
Day 071 の次回予告どおり「実装」。Day 071 では「記録は最外側の Edge が 1 回だけ書く」と決めた。ただし解答は標準ライブラリだけで、OTel とつないでいなかった。今日は本物の OTel SDK(otel v1.45.0・otelhttp v0.70.0)につなぐ。Day 071 の実測 2 で空いていた欄(S5・S6 の span 状態とメトリクス、S7 の 200)を全場面で埋め、テストで固定する。
📚 背景知識(読んでから問題へ)
Day 071 の終わりに残っていたもの
Day 071 の実測 2 では、otelhttp v0.70.0 を最外側に置いただけだと次のようになりました。
| 場面 | span の状態 | span の http.response.status_code | otelhttp のメトリクス |
|---|---|---|---|
| S5 送信後の error | Unset | なし | 0 点 |
| S6 送信後の panic | Unset | なし | 0 点 |
| S7 相手が先に切った | Unset | 200 | 1 点(200) |
決めたことは 3 つです。
- メトリクスは Edge が書く。otelhttp は
next.ServeHTTPの後でメトリクスを書く(handler.go203 行。defer の中ではない)ので、panic が通り抜ける S5・S6 の点が消える - トレースは otelhttp に任せる。ただし otelhttp が届かない所(S5・S6)は Edge が span に Error を付ける
- ログの 1 行からトレースに飛べるようにする(trace_id を載せる)
今日はこの 3 つを、本物の SDK を相手に実装します。
今日使う実物(一次資料。2026-10-12 に手元のモジュールキャッシュで読んだ)
| 実物 | 今日に関わる所 | 場所 |
|---|---|---|
| otelhttp v0.70.0 | defer span.End() は 128 行。next.ServeHTTP が 185 行、span の状態は 193 行、メトリクスは 203 行(どちらも defer ではない)。何も書かれなければ 200 とみなす | handler.go、internal/request/resp_writer_wrapper.go 40 行 |
| otelhttp の server 側 semconv | span の状態は 5xx だけ Error(server.go 64〜78 行)。**server 側のメトリクスにも span にも error.type を付けない**(error.type を書くのは transport.go と client.go。クライアント側だけ) | internal/semconv/server.go・client.go 284 行 |
| otelhttp の method の扱い | 大文字にしてから、既知の 9 つ以外を _OTHER にまとめる | internal/semconv/util.go 120〜128 行 |
**semconv v1.43.0 error.type** | "SHOULD be predictable, and SHOULD have low cardinality"、"If the operation has completed successfully, instrumentations SHOULD NOT set error.type" | otel@v1.45.0/semconv/v1.43.0/attribute_group.go 4743〜4785 行 |
**httpconv.NewServerRequestDuration** | 名前 http.server.request.duration・単位 s・バケット境界 0.005〜10 の 14 個 | semconv/v1.43.0/httpconv/metric.go 1685〜1715 行 |
| OTel Go SDK の span | SetAttributes: "If a key from attributes already exists the value associated with that key will be overwritten"(後から書いた方が勝つ) | sdk@v1.45.0/trace/span.go 229〜230 行 |
| OTel Go SDK のメトリクス | 既定の exemplar フィルタは TraceBasedFilter(サンプルされた span が ctx にあれば、点に trace_id を付ける) | sdk/metric@v1.45.0/config.go 81 行 |
| log/slog(Go 1.27.1) | Record.AddAttrs は Record の写しに足すと !BUG 属性を出す仕組みを持つ(Handler の中で足すのは正しい使い方) | log/slog/record.go 97〜116 行 |
otelslog(go.opentelemetry.io/contrib/bridges/otelslog) | slog をそのまま OTel の Logs に流す橋 | 手元に無く、今回は読んでいない・動かしていない |
用語
| 用語 | 意味 |
|---|---|
| semconv | OpenTelemetry Semantic Conventions。属性の名前と意味の取り決め(http.route・http.response.status_code・error.type など)。同じ名前で出せば、既製のダッシュボードやアラートがそのまま使える |
| exemplar | メトリクスの点に付く「代表の 1 件」。trace_id を持つので、グラフの点からそのリクエストのトレースに飛べる |
| 系列の数(カーディナリティ) | 属性の値の組み合わせの数。user や任意の文字列を入れると上限なく増える |
| request_id | 自分のサービスが 1 リクエストに付ける番号。trace_id は分散トレース全体(複数のサービスにまたがる)の番号 |
📝 問題
状況
Day 071 の決定に従い、/export の観測を本物の OTel につなぎます。基盤チームからの条件は 3 つです。
- メトリクス:
http.server.request.durationを OTel HTTP semconv の名前と属性で出す(社内の既製ダッシュボードがこの名前を前提にしている)。1 リクエストにつき 1 点だけ(otelhttp と Edge の二重計上は不可) - トレース: otelhttp v0.70.0 を使う。S1〜S8 のどの場面でも span の状態と
http.response.status_codeが正しいこと - ログ: Edge の 1 行にも、ハンドラが
slogで書いた行にも、同じ trace_id と request_id が自動で付くこと。外から来たX-Request-Idは、安全なものだけ引き継ぐ
課題
edge.go に次を実装し、edge_test.go の O1〜O11 を -race 付きで通してください。
type LogHandler struct{ slog.Handler } // trace_id・span_id・request_id を足す slog.Handler
func NewLogHandler(h slog.Handler) *LogHandler
func Edge(log *slog.Logger, mp metric.MeterProvider, routeOf func(*http.Request) string) func(http.Handler) http.Handler
func Traced(h http.Handler, tp trace.TracerProvider, routeOf func(*http.Request) string) http.Handler // otelhttp をトレースだけに
func Stack(h HandlerE, log *slog.Logger, tp trace.TracerProvider, mp metric.MeterProvider, routeOf func(*http.Request) string) http.Handler
func SLIFrom(rm metricdata.ResourceMetrics) float64 // メトリクスだけから可用性
各場面で出すべきもの(テストの期待値と同じ):
| 場面 | メトリクスの属性(method・scheme・route に加えて) | span の状態 | span の status_code | span の error.type | ログ |
|---|---|---|---|---|---|
| S1 成功 | status_code=200 | Unset | 200 | — | INFO ok |
| S2 404 | status_code=404 | Unset | 404 | — | INFO client_error |
| S3 送信前の error | status_code=500, error.type=500 | Error | 500 | 500 | ERROR server_error |
| S4 送信前の panic | status_code=500, error.type=500 | Error | 500 | 500 | ERROR server_error+stack |
| S5 送信後の error | status_code=200, error.type=aborted | Error | 200 | aborted | ERROR aborted |
| S6 送信後の panic | status_code=200, error.type=aborted | Error | 200 | aborted | ERROR aborted+stack |
| S7 相手が先に切った | status_code=499 | Unset | 499 | — | INFO client_closed |
| S8 期限切れ | status_code=503, error.type=503 | Error | 503 | 503 | ERROR server_error |
| (O8)Recover なしで S4 | status_code なし, error.type=aborted | Error | なし | aborted | ERROR aborted, status=0 |
予想してから解く(自己評価欄へ)
- P1: S7 で span の status_code を 499 にしたい。Edge の defer で
span.SetAttributes(attribute.Int("http.response.status_code", 499))と書けば直るか - P2:
otelhttp.WithMeterProviderを指定せず、Edge と同じ MeterProvider を otelhttp にも渡すと、O1 で何が起きるか - P3: exemplar(trace_id 付きの代表点)は、失敗の点だけに付くか、成功の点にも付くか
準備
mkdir d72 && cd d72 # 作業ディレクトリを作って入る
printf 'module d72\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 を入れる(筆者はキャッシュ済みのため GOPROXY=off で実行)
# Day 069 の types.go・adapt.go、Day 071 の recover.go をそのまま置く(変えない)
# 下の bag.go・edge_test.go を保存し、edge.go を書く
go test -race -count=1 -v ./... # O1〜O11 がすべて PASS すれば完成
ファイル: bag.go(Day 071 の edge.go から袋と class を取り出したもの。RequestID を足しただけ。変えない)
bag.go(74 行)
package main
import (
"context"
"net/http"
"runtime/debug"
)
// Outcome は 1 リクエストの「事実」を集める袋(Day 071 と同じ。RequestID だけ足した)。
// 中の部品は書き込むだけで、出力は Edge の defer が 1 回だけ行う。
type Outcome struct {
RequestID string
User string
Err error
ErrStatus int
Panic any
Stack []byte
}
type outcomeKey struct{}
func outcomeFrom(ctx context.Context) *Outcome {
o, _ := ctx.Value(outcomeKey{}).(*Outcome)
return o
}
func outcomeOf(r *http.Request) *Outcome { return outcomeFrom(r.Context()) }
// ErrInto は Adapt に渡す LogFunc。記録せずに袋に書く(先勝ち)。
func ErrInto(r *http.Request, status int, err error) {
if o := outcomeOf(r); o != nil && o.Err == nil {
o.Err, o.ErrStatus = err, status
}
}
// PanicInto は Recover に渡す。panic の場所はこの時点のスタックにしか無い。
func PanicInto(r *http.Request, p any) {
if o := outcomeOf(r); o != nil && o.Panic == nil {
o.Panic, o.Stack = p, debug.Stack()
}
}
// Identify は認証の代役。誰のリクエストかを袋に書く。
func Identify(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
if o := outcomeOf(r); o != nil {
o.User = r.Header.Get("X-User")
}
next.ServeHTTP(w, r)
})
}
// class はログの 1 行にだけ出す分類(Day 071 と同じ 5 値)。メトリクスには出さない(今日の決定)。
const (
ClassOK = "ok"
ClassClientError = "client_error"
ClassClientClosed = "client_closed"
ClassServerError = "server_error"
ClassAborted = "aborted"
)
func classOf(status int, aborted bool) string {
switch {
case aborted:
return ClassAborted
case status == StatusClientClosed:
return ClassClientClosed
case status >= 500:
return ClassServerError
case status >= 400:
return ClassClientError
}
return ClassOK
}
ファイル: edge_test.go(変えない。O1〜O11)
edge_test.go(483 行)
package main
import (
"bytes"
"context"
"encoding/json"
"errors"
"fmt"
"io"
"log"
"log/slog"
"net/http"
"net/http/httptest"
"sort"
"strings"
"sync"
"testing"
"go.opentelemetry.io/otel/codes"
sdkmetric "go.opentelemetry.io/otel/sdk/metric"
"go.opentelemetry.io/otel/sdk/metric/metricdata"
sdktrace "go.opentelemetry.io/otel/sdk/trace"
"go.opentelemetry.io/otel/sdk/trace/tracetest"
)
// ---- 出口の受け皿 ----
type lockedBuf struct {
mu sync.Mutex
b bytes.Buffer
}
func (l *lockedBuf) Write(p []byte) (int, error) {
l.mu.Lock()
defer l.mu.Unlock()
return l.b.Write(p)
}
func (l *lockedBuf) lines(t *testing.T) []map[string]any {
l.mu.Lock()
defer l.mu.Unlock()
var out []map[string]any
for _, s := range strings.Split(strings.TrimSpace(l.b.String()), "\n") {
if s == "" {
continue
}
var m map[string]any
if err := json.Unmarshal([]byte(s), &m); err != nil {
t.Fatalf("JSON でない行: %q", s)
}
out = append(out, m)
}
return out
}
// rig は本物の OTel SDK(span は SpanRecorder、メトリクスは ManualReader)につないだ Stack。
type rig struct {
buf *lockedBuf
sr *tracetest.SpanRecorder
rd *sdkmetric.ManualReader
tp *sdktrace.TracerProvider
mp *sdkmetric.MeterProvider
log *slog.Logger
}
func newRig() *rig {
g := &rig{buf: &lockedBuf{}, sr: tracetest.NewSpanRecorder(), rd: sdkmetric.NewManualReader()}
g.tp = sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(g.sr))
g.mp = sdkmetric.NewMeterProvider(sdkmetric.WithReader(g.rd))
g.log = slog.New(NewLogHandler(slog.NewJSONHandler(g.buf, nil)))
return g
}
func (g *rig) stack(h HandlerE) http.Handler { return Stack(h, g.log, g.tp, g.mp, route) }
type point struct {
name string
attrs map[string]string
count uint64
exTID []string // exemplar の trace_id
}
func (g *rig) points(t *testing.T) []point {
t.Helper()
var rm metricdata.ResourceMetrics
if err := g.rd.Collect(context.Background(), &rm); err != nil {
t.Fatal(err)
}
var out []point
for _, sm := range rm.ScopeMetrics {
for _, m := range sm.Metrics {
h, ok := m.Data.(metricdata.Histogram[float64])
if !ok {
out = append(out, point{name: m.Name + "(非ヒストグラム)"})
continue
}
for _, dp := range h.DataPoints {
p := point{name: m.Name, attrs: map[string]string{}, count: dp.Count}
for _, kv := range dp.Attributes.ToSlice() {
p.attrs[string(kv.Key)] = kv.Value.Emit()
}
for _, ex := range dp.Exemplars {
p.exTID = append(p.exTID, fmt.Sprintf("%x", ex.TraceID))
}
out = append(out, p)
}
}
}
return out
}
func spanAttr(s sdktrace.ReadOnlySpan, key string) (string, bool) {
for _, kv := range s.Attributes() {
if string(kv.Key) == key {
return kv.Value.Emit(), true
}
}
return "", false
}
func route(*http.Request) string { return "GET /export" }
// ---- 8 つの場面(Day 071 と同じハンドラ) ----
func explodeBeforeCommit(w http.ResponseWriter, r *http.Request) error {
var m map[string]int
m["x"]++
return nil
}
func explodeAfterCommit(w http.ResponseWriter, r *http.Request) error {
io.WriteString(w, "id,name\n1,alice\n")
http.NewResponseController(w).Flush()
var m map[string]int
m["x"]++
return nil
}
func streamThenFail(w http.ResponseWriter, r *http.Request) error {
io.WriteString(w, "id,name\n1,alice\n")
http.NewResponseController(w).Flush()
return errors.New("rows.Next: driver: bad connection")
}
func okHandler(w http.ResponseWriter, r *http.Request) error { io.WriteString(w, "ok"); return nil }
type scenario struct {
name string
h HandlerE
clientGone bool
status int // ログ・メトリクス・span の status(0 = 送っていない)
errType string // メトリクスと span の error.type("" = 付けない)
spanErr bool // span の状態が Error か
class string
level string
errSub string
panicFn string
}
var scenarios = []scenario{
{"S1 成功", okHandler, false, 200, "", false, ClassOK, "INFO", "", ""},
{"S2 404", func(w http.ResponseWriter, r *http.Request) error { return fmt.Errorf("repo.Get(42): %w", ErrNotFound) },
false, 404, "", false, ClassClientError, "INFO", "repo.Get(42)", ""},
{"S3 送信前の error", func(w http.ResponseWriter, r *http.Request) error { return errors.New("pq: connection refused") },
false, 500, "500", true, ClassServerError, "ERROR", "connection refused", ""},
{"S4 送信前の panic", explodeBeforeCommit, false, 500, "500", true, ClassServerError, "ERROR", "", "explodeBeforeCommit"},
{"S5 送信後の error", streamThenFail, false, 200, "aborted", true, ClassAborted, "ERROR", "bad connection", ""},
{"S6 送信後の panic", explodeAfterCommit, false, 200, "aborted", true, ClassAborted, "ERROR", "", "explodeAfterCommit"},
{"S7 相手が先に切った", func(w http.ResponseWriter, r *http.Request) error { return fmt.Errorf("query: %w", r.Context().Err()) },
true, 499, "", false, ClassClientClosed, "INFO", "context canceled", ""},
{"S8 期限切れ", func(w http.ResponseWriter, r *http.Request) error {
return fmt.Errorf("query: %w", context.DeadlineExceeded)
},
false, 503, "503", true, ClassServerError, "ERROR", "deadline exceeded", ""},
}
type result struct {
g *rig
code int
readErr error
ridHdr string
lines []map[string]any
spans []sdktrace.ReadOnlySpan
points []point
}
func run(t *testing.T, sc scenario, hdr map[string]string) result {
t.Helper()
g := newRig()
h := g.stack(sc.h)
res := result{g: g}
if sc.clientGone {
ctx, cancel := context.WithCancel(context.Background())
cancel()
r := httptest.NewRequest("GET", "/export", nil).WithContext(ctx)
r.Header.Set("X-User", "alice")
for k, v := range hdr {
r.Header.Set(k, v)
}
rec := httptest.NewRecorder()
h.ServeHTTP(rec, r)
res.ridHdr = rec.Header().Get("X-Request-Id")
} else {
srv := httptest.NewServer(h)
req, _ := http.NewRequest("GET", srv.URL+"/export", nil)
req.Header.Set("X-User", "alice")
for k, v := range hdr {
req.Header.Set(k, v)
}
resp, err := http.DefaultClient.Do(req)
if err != nil {
res.readErr = err
} else {
_, err = io.ReadAll(resp.Body)
resp.Body.Close()
res.code, res.readErr, res.ridHdr = resp.StatusCode, err, resp.Header.Get("X-Request-Id")
}
srv.Close()
}
res.lines, res.spans, res.points = g.buf.lines(t), g.sr.Ended(), g.points(t)
return res
}
// O1: メトリクスは Edge の 1 点だけ(otelhttp は書かない)。名前と属性は OTel HTTP semconv のとおり。
func TestO1_OneSemconvPoint(t *testing.T) {
for _, sc := range scenarios {
r := run(t, sc, nil)
want := map[string]string{"http.request.method": "GET", "url.scheme": "http", "http.route": "GET /export"}
if sc.status != 0 {
want["http.response.status_code"] = fmt.Sprint(sc.status)
}
if sc.errType != "" {
want["error.type"] = sc.errType
}
if len(r.points) != 1 || r.points[0].name != "http.server.request.duration" || r.points[0].count != 1 ||
fmt.Sprint(r.points[0].attrs) != fmt.Sprint(want) {
t.Errorf("%s: points=%+v; want 1 点 %v", sc.name, r.points, want)
}
}
}
// O2: span は 1 本。状態・status_code・error.type が全場面で埋まる(otelhttp だけでは S5・S6 が Unset・status なし、S7 が 200)。
func TestO2_SpanFilledEverywhere(t *testing.T) {
for _, sc := range scenarios {
r := run(t, sc, nil)
if len(r.spans) != 1 {
t.Errorf("%s: span %d 本", sc.name, len(r.spans))
continue
}
s := r.spans[0]
if (s.Status().Code == codes.Error) != sc.spanErr {
t.Errorf("%s: span status=%v; want Error=%v", sc.name, s.Status(), sc.spanErr)
}
if got, _ := spanAttr(s, "http.response.status_code"); got != fmt.Sprint(sc.status) {
t.Errorf("%s: span status_code=%q; want %d", sc.name, got, sc.status)
}
if got, _ := spanAttr(s, "error.type"); got != sc.errType {
t.Errorf("%s: span error.type=%q; want %q", sc.name, got, sc.errType)
}
if s.Name() != "GET /export" {
t.Errorf("%s: span name=%q", sc.name, s.Name())
}
}
}
// O3: ログは 1 行。Day 071 の中身に加え、trace_id・span_id が span と一致し、request_id が応答ヘッダと一致する。
func TestO3_LogJoinsTrace(t *testing.T) {
for _, sc := range scenarios {
r := run(t, sc, nil)
if len(r.lines) != 1 || len(r.spans) != 1 {
t.Errorf("%s: lines=%d spans=%d", sc.name, len(r.lines), len(r.spans))
continue
}
l, sp := r.lines[0], r.spans[0].SpanContext()
if l["level"] != sc.level || l["class"] != sc.class || l["status"] != float64(sc.status) || l["user"] != "alice" {
t.Errorf("%s: level=%v class=%v status=%v user=%v", sc.name, l["level"], l["class"], l["status"], l["user"])
}
if l["trace_id"] != sp.TraceID().String() || l["span_id"] != sp.SpanID().String() {
t.Errorf("%s: log trace=%v span=%v; span は %s %s", sc.name, l["trace_id"], l["span_id"], sp.TraceID(), sp.SpanID())
}
if rid, _ := l["request_id"].(string); rid == "" || rid != r.ridHdr {
t.Errorf("%s: request_id=%q 応答ヘッダ=%q", sc.name, rid, r.ridHdr)
}
e, hasErr := l["err"].(string)
if (sc.errSub != "") != hasErr || !strings.Contains(e, sc.errSub) {
t.Errorf("%s: err=%q; want 含む %q", sc.name, e, sc.errSub)
}
st, hasStack := l["stack"].(string)
if (sc.panicFn != "") != hasStack || !strings.Contains(st, sc.panicFn) {
t.Errorf("%s: stack に %q が無い", sc.name, sc.panicFn)
}
}
}
// O4: 来た X-Request-Id は、短く安全な文字だけなら引き継ぐ。改行入り・65 文字は作り直す。
func TestO4_RequestIDInput(t *testing.T) {
cases := []struct {
in string
keep bool
}{
{"abc-123_X.y", true},
{strings.Repeat("a", 64), true},
{strings.Repeat("a", 65), false},
{"x\" level=ERROR", false},
{"", false},
}
for _, c := range cases {
r := run(t, scenarios[0], map[string]string{"X-Request-Id": c.in})
if len(r.lines) != 1 {
t.Fatalf("in=%q: ログ %d 行", c.in, len(r.lines))
}
rid, _ := r.lines[0]["request_id"].(string)
if c.keep && rid != c.in || !c.keep && (rid == c.in || len(rid) != 16) || rid != r.ridHdr {
t.Errorf("in=%q: request_id=%q 応答ヘッダ=%q keep=%v", c.in, rid, r.ridHdr, c.keep)
}
}
}
// O5: 失敗の点には exemplar が付き、その trace_id が span と同じ(メトリクスからトレースへ飛べる)。
func TestO5_ExemplarLinksTrace(t *testing.T) {
for _, sc := range []scenario{scenarios[2], scenarios[4], scenarios[5]} { // S3・S5・S6
r := run(t, sc, nil)
if len(r.points) != 1 || len(r.spans) != 1 {
t.Fatalf("%s: points=%d spans=%d", sc.name, len(r.points), len(r.spans))
}
tid := r.spans[0].SpanContext().TraceID().String()
if len(r.points[0].exTID) != 1 || r.points[0].exTID[0] != tid {
t.Errorf("%s: exemplar=%v; want [%s]", sc.name, r.points[0].exTID, tid)
}
}
}
// serve は実サーバーを通さずに呼ぶ。送信後の切断は panic(http.ErrAbortHandler) で出てくるので受け止める。
func serve(h http.Handler, r *http.Request) {
defer func() {
if p := recover(); p != nil && p != http.ErrAbortHandler {
panic(p)
}
}()
h.ServeHTTP(httptest.NewRecorder(), r)
}
// O6: SLI はメトリクスだけから出る。499 は分母から外し、aborted と 5xx は失敗、4xx は成功。
func TestO6_SLIFromMetrics(t *testing.T) {
g := newRig()
mix := []struct {
sc scenario
n int
}{{scenarios[0], 900}, {scenarios[1], 40}, {scenarios[6], 30}, {scenarios[4], 20}, {scenarios[2], 10}}
for _, m := range mix {
h := g.stack(m.sc.h)
for i := 0; i < m.n; i++ {
r := httptest.NewRequest("GET", "/export", nil)
if m.sc.clientGone {
ctx, cancel := context.WithCancel(context.Background())
cancel()
r = r.WithContext(ctx)
}
serve(h, r)
}
}
var rm metricdata.ResourceMetrics
g.rd.Collect(context.Background(), &rm)
if got, want := SLIFrom(rm), 940.0/970.0; got != want {
t.Fatalf("SLI=%v; want %v", got, want)
}
if SLIFrom(metricdata.ResourceMetrics{}) != 1 {
t.Fatal("点が無ければ 1")
}
}
// O7: 200 本同時。ログの trace_id は 200 種類で、span の集合と一致し、user と err が混ざらない(-race で)。
func TestO7_Concurrent(t *testing.T) {
g := newRig()
h := g.stack(func(w http.ResponseWriter, r *http.Request) error {
if u := r.Header.Get("X-User"); u[len(u)-1]%2 == 0 {
return fmt.Errorf("fail for %s", u)
}
io.WriteString(w, "ok")
return nil
})
var wg sync.WaitGroup
for i := 0; i < 200; i++ {
wg.Add(1)
go func(i int) {
defer wg.Done()
r := httptest.NewRequest("GET", "/export", nil)
r.Header.Set("X-User", fmt.Sprintf("u%03d", i))
h.ServeHTTP(httptest.NewRecorder(), r)
}(i)
}
wg.Wait()
lines, spans := g.buf.lines(t), g.sr.Ended()
var fromLog, fromSpan []string
for _, l := range lines {
u, _ := l["user"].(string)
e, hasErr := l["err"].(string)
if hasErr != (u[len(u)-1]%2 == 0) || (hasErr && e != "fail for "+u) {
t.Fatalf("混ざった: user=%s err=%q", u, e)
}
fromLog = append(fromLog, fmt.Sprint(l["trace_id"]))
}
for _, s := range spans {
fromSpan = append(fromSpan, s.SpanContext().TraceID().String())
}
sort.Strings(fromLog)
sort.Strings(fromSpan)
uniq := map[string]bool{}
for _, s := range fromLog {
uniq[s] = true
}
if len(lines) != 200 || len(uniq) != 200 || strings.Join(fromLog, ",") != strings.Join(fromSpan, ",") {
t.Fatalf("lines=%d 種類=%d spans=%d 一致=%v", len(lines), len(uniq), len(spans), strings.Join(fromLog, ",") == strings.Join(fromSpan, ","))
}
}
// O8: Recover を付け忘れて S4。何も送らずに切ったので status は 0(メトリクスに status_code なし)、error.type=aborted。
func TestO8_NoRecoverNothingSent(t *testing.T) {
g := newRig()
h := Traced(Edge(g.log, g.mp, route)(Identify(Adapt(explodeBeforeCommit, ErrInto))), g.tp, route) // Recover なし
srv := httptest.NewUnstartedServer(h)
srv.Config.ErrorLog = log.New(io.Discard, "", 0)
srv.Start()
_, err := http.Get(srv.URL)
srv.Close()
pts, lines, spans := g.points(t), g.buf.lines(t), g.sr.Ended()
want := map[string]string{"http.request.method": "GET", "url.scheme": "http", "http.route": "GET /export", "error.type": "aborted"}
if err == nil || len(pts) != 1 || fmt.Sprint(pts[0].attrs) != fmt.Sprint(want) {
t.Fatalf("err=%v points=%+v", err, pts)
}
if len(lines) != 1 || lines[0]["status"] != float64(0) || !strings.Contains(fmt.Sprint(lines[0]["stack"]), "explodeBeforeCommit") {
t.Fatalf("lines=%v", lines)
}
if len(spans) != 1 {
t.Fatalf("span %d 本", len(spans))
}
if _, has := spanAttr(spans[0], "http.response.status_code"); has || spans[0].Status().Code != codes.Error {
t.Fatalf("span status=%v status_code あり=%v", spans[0].Status(), has)
}
}
// O9: クライアントに届くもの(Day 071 の R5 と同じ約束)。送信後の失敗は完全な 200 にしない。
func TestO9_ClientView(t *testing.T) {
for _, sc := range scenarios[2:6] { // S3〜S6
r := run(t, sc, nil)
if sc.class == ClassAborted {
if !errors.Is(r.readErr, io.ErrUnexpectedEOF) {
t.Errorf("%s: readErr=%v; want unexpected EOF", sc.name, r.readErr)
}
} else if r.readErr != nil || r.code != sc.status {
t.Errorf("%s: %d %v", sc.name, r.code, r.readErr)
}
}
}
// O10: 未知のメソッドは _OTHER にまとめる(任意の文字列で系列を増やされない)。
func TestO10_UnknownMethod(t *testing.T) {
g := newRig()
h := g.stack(okHandler)
for _, m := range []string{"PROPFIND", "X-SCAN-1", "X-SCAN-2"} {
h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(m, "/export", nil))
}
pts := g.points(t)
if len(pts) != 1 || pts[0].attrs["http.request.method"] != "_OTHER" || pts[0].count != 3 {
t.Fatalf("points=%+v; want _OTHER の 1 系列に 3 件", pts)
}
}
// O11: ハンドラが logger.With(...) で書いた行にも、同じ trace_id・request_id が付く。
func TestO11_HandlerLogWithAttrs(t *testing.T) {
g := newRig()
jobLog := g.log.With("job", "export")
h := g.stack(func(w http.ResponseWriter, r *http.Request) error {
jobLog.InfoContext(r.Context(), "rows", "n", 2)
io.WriteString(w, "ok")
return nil
})
h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/export", nil))
lines := g.buf.lines(t)
if len(lines) != 2 || lines[0]["job"] != "export" || lines[0]["trace_id"] == nil ||
lines[0]["trace_id"] != lines[1]["trace_id"] || lines[0]["request_id"] != lines[1]["request_id"] {
t.Fatalf("lines=%v", lines)
}
}
💡 ヒント
ヒント1(方向性)
3 つの出口は、どれも「Edge の defer の時点で r.Context() に何が入っているか」で決まります。otelhttp は Edge の外にあるので、Edge が受け取る r.Context() にはもう span が入っています。その ctx を、メトリクスの Record・span の操作・slog の 3 つすべてに渡してください。
ヒント2(アプローチ)
- メトリクス:
httpconv.NewServerRequestDuration(mp.Meter(...))で semconv どおりの名前・単位・バケットのヒストグラムが作れる。Record(ctx, 秒, method, scheme, attrs...)。status_codeは送ったときだけ、error.typeは失敗のときだけ付ける - 二重計上を止める: otelhttp には
otelhttp.WithMeterProvider(noop.NewMeterProvider())を渡す - S5・S6 の span: otelhttp は panic が通り抜けると 193 行に届かない。だから Edge が
trace.SpanFromContext(ctx).SetStatus(codes.Error, …)と status_code を書く。otelhttp が後から上書きすることも無い(届かないので) - S7 の span: 予想 P1 を確かめる。otelhttp は Edge が戻った後に status_code を書く。SDK の
SetAttributesは後勝ち。では otelhttp が読む値(rww.StatusCode())そのものを 499 にするには? - ログ:
slog.Handlerを包み、Handle(ctx, rec)の中でtrace.SpanContextFromContext(ctx)と袋から値を取りrec.AddAttrs(...)する。WithAttrs・WithGroupも包み直して返す(O11) - request_id: 外から来た値は長さと文字種を見る。ダメなら
crypto/randで 8 バイト → 16 桁の 16 進
ヒント3(コード骨格)
func Edge(log *slog.Logger, mp metric.MeterProvider, routeOf func(*http.Request) string) func(http.Handler) http.Handler {
dur, _ := httpconv.NewServerRequestDuration(mp.Meter("d72/edge"))
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
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()
// status: aborted で 0 → 0 のまま(何も送っていない)
// aborted でなく 0 → 200。ctx が切れていれば 499 にして ow.WriteHeader(499)
// dur.Record(r.Context(), …) ← exemplar のため ctx を渡す
// span := trace.SpanFromContext(r.Context()) ← error.type、aborted なら Error と status_code
// log.LogAttrs(r.Context(), level, "request", …) ← LogHandler が trace_id を足す
// p != nil → panic(p)
}()
next.ServeHTTP(ow, r)
})
}
}
✅ 模範解答
edge.go(216 行)
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"
"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("d72/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.WithSpanNameFormatter(func(_ string, r *http.Request) string { return routeOf(r) }))
}
// 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)
}
実行結果(Go 1.27.1、otel v1.45.0・otelhttp v0.70.0、2026-10-12、M1 MacBook Pro 8GB)
$ GOPROXY=off go test -race -count=1 -v ./... 2>&1 | grep -E '^(---|ok)'
--- PASS: TestO1_OneSemconvPoint (0.04s)
--- PASS: TestO2_SpanFilledEverywhere (0.02s)
--- PASS: TestO3_LogJoinsTrace (0.02s)
--- PASS: TestO4_RequestIDInput (0.01s)
--- PASS: TestO5_ExemplarLinksTrace (0.01s)
--- PASS: TestO6_SLIFromMetrics (0.14s)
--- PASS: TestO7_Concurrent (0.07s)
--- PASS: TestO8_NoRecoverNothingSent (0.00s)
--- PASS: TestO9_ClientView (0.01s)
--- PASS: TestO10_UnknownMethod (0.00s)
--- PASS: TestO11_HandlerLogWithAttrs (0.00s)
ok d72 1.749s
各場面で 3 つの出口に出たもの(ログは time を除き、stack は長さに置き換えた。ID は実行ごとに変わる):
S1 log {class:ok level:INFO status:200 user:alice trace_id:40f4249f… span_id:05f292b8… request_id:31bcdebd190ff353 …}
span {Unset status_code=200}
点 {method=GET route="GET /export" status_code=200 url.scheme=http} exemplar=[40f4249f…]
S5 log {class:aborted level:ERROR status:200 err:"rows.Next: driver: bad connection" trace_id:d4e6e828… …}
span {Error status_code=200 error.type=aborted}
点 {… status_code=200 error.type=aborted} exemplar=[d4e6e828…]
S6 log {class:aborted level:ERROR status:200 panic:"assignment to entry in nil map" stack:3405 trace_id:e473a999… …}
span {Error status_code=200 error.type=aborted}
点 {… status_code=200 error.type=aborted} exemplar=[e473a999…]
S7 log {class:client_closed level:INFO status:499 err:"query: context canceled" trace_id:0984aa33… …}
span {Unset status_code=499}
点 {… status_code=499} exemplar=[0984aa33…]
(S2・S3・S4・S8 も問題の表のとおり。exemplar の trace_id は 8 場面すべてで span の trace_id と一致)
🪜 Step-by-Step 解説
Step 1: 積む順を決める——otelhttp が外、Edge がすぐ内側
otelhttp(span を作る・トレースだけ) → Edge(袋・3 出口に 1 回ずつ) → Identify → Recover → Adapt → ハンドラ
Edge の r.Context() に span が入っているのは、otelhttp が外にあるときだけです。逆に置くと(変異 M19)、Edge のログに trace_id が無く、exemplar も付かず、Edge が付けた span の状態も効きません(O2・O3・O5・O7・O11 が落ちる)。
Step 2: メトリクスは semconv の部品で作り、属性は「送ったときだけ」「失敗のときだけ」
httpconv.NewServerRequestDuration を使うと、名前・単位・説明・バケット境界が otelhttp と同じになります。自分で "http.server.request.duration" と書くより、綴りの間違いが起きません。
| 属性 | 付ける条件 | 理由 |
|---|---|---|
http.request.method | 常に。未知のメソッドは _OTHER | 任意の文字列で系列を増やされない(O10) |
url.scheme・http.route | 常に | route はパターン(GET /export)。生のパスは入れない(Day 063) |
http.response.status_code | 送ったときだけ | O8(Recover の付け忘れ)では何も送っていない。0 を書くと「0 番の応答」という存在しない系列ができる |
error.type | 5xx と aborted だけ | semconv は成功に付けないよう求める。値は 5xx なら番号の文字列、送信後の切断は aborted。値の集合は小さく固定 |
Day 071 の class(5 値)はメトリクスの属性から外しました。status_code と error.type から一意に決まるからです(下の「迷った他案」)。
Step 3: span は「otelhttp が届かない所」だけ Edge が書く
- S5・S6: panic が Edge を通り抜けて otelhttp まで行くので、otelhttp の 193 行(状態)と 195 行(status_code などの属性)に届きません。Edge が defer の中で
SetStatus(codes.Error, "aborted")と status_code を書きます。otelhttp はその後何も書かないので、Edge の値が残ります - S3・S4・S8: otelhttp が状態(Error)と status_code を書きます。Edge は
error.typeだけを足します(otelhttp の server 側は付けない) - S7: 予想 P1 の答え。
span.SetAttributes(status_code=499)は効きません。Edge が戻った後で otelhttp がrww.StatusCode()(何も書かれなければ 200)を書き、SDK のSetAttributesは後勝ちだからです(変異 M3 で実測: span の status_code は "200")。そこで Edge は **ow.WriteHeader(499)を実際に呼びます**。otelhttp が包んだ writer がこの 499 を覚え、span に 499 を書きます。相手はもう切っているので、この 499 は誰にも届きません
Step 4: ログは Handler で足す——「Edge の 1 行」以外にも効かせるため
LogHandler.Handle は ctx から trace_id・span_id と袋の request_id を取り出して rec.AddAttrs します。Edge の 1 行に直接書かずに Handler で足す理由は、ハンドラが自分で書いた行にも同じ鍵が付くからです(O11)。ただしハンドラが slog.Info(...)(ctx なし)で書くと付きません。InfoContext(r.Context(), ...) を使う必要があります。
WithAttrs・WithGroup を包み直さないと、logger.With("job", "export") で作ったロガーは LogHandler を素通りします(変異 M20。O11 を足すまで生存)。
Step 5: request_id は「信じるが、確かめる」
外から来た X-Request-Id は、上流(ロードバランサや呼び出し元)の ID と自分のログをつなぐのに役立ちます。でも中身は利用者が自由に書けます。今日は **1〜64 文字、英数字と - _ . だけ**を引き継ぎ、それ以外は作り直しました。改行や " 入りの値(ログの偽造を狙う形)、65 文字以上は O4 で作り直されることを確かめています。
Step 6: SLI はメトリクスだけから出す
SLIFrom は Edge が書いた点だけを読みます。
- 分母:
status_code=499の点を除いたすべて - 失敗:
error.typeが付いた点(5xx と aborted)
Day 071 で決めた規則(499 は外す・aborted は失敗・4xx は成功)が、semconv の属性だけで表せます。仮定の配分(ok 900・404 が 40・499 が 30・aborted 20・500 が 10)で 940 / 970 = 96.91%(O6)。Day 071 の SLI(map) と同じ値です。
📏 実測(予想と外れた所を含む)
1. 前後比較: otelhttp だけ(Day 071 実測 2)と今日の Stack
| 場面 | span 状態(前→後) | span status_code(前→後) | メトリクスの点(前→後) | ログの trace_id |
|---|---|---|---|---|
| S5 | Unset → Error | なし → 200 | 0 → 1(error.type=aborted) | 無し → span と一致 |
| S6 | Unset → Error | なし → 200 | 0 → 1(error.type=aborted) | 無し → span と一致 |
| S7 | Unset → Unset | 200 → 499 | 1(200)→ 1(499) | 無し → span と一致 |
| S3・S4・S8 | Error → Error | 同じ | 1 → 1(error.type を追加) | 無し → span と一致 |
| S1・S2 | Unset → Unset | 同じ | 1 → 1 | 無し → span と一致 |
2. 予想の答え合わせ
- P1(S7 を span 属性で 499 に): 効かない。変異 M3 で span の status_code は
"200"。otelhttp が Edge の後で書き、SDK は後勝ち(span.go229〜230 行)。ow.WriteHeader(499)で otelhttp が読む値そのものを変えると 499 になる(O2) - P2(otelhttp にも本物の MeterProvider): 変異 M4。予想は「同じヒストグラムの Count が 2 になる」だったが外れた。実際は
http.server.request.durationという同じ名前の点が別々に 2 つできた(otelhttp の点はserver.address・server.port・network.protocol.*を持ち、属性の組が違うため)。加えて otelhttp のhttp.server.request.body.size・response.body.sizeが出る。ダッシュボードが名前だけで合計すると要求数が倍に見える。otelhttp の点(S5 の 20 件は届かず、S7 は 499 で外れるので 950 件)には error.type が無く、全部「成功」として分母に足される。O6 の SLI は 940/970 = 96.91% → 1,890/1,920 = 98.44% に上がった(導出と実測が一致)。O1・O5・O6・O10 が落ちる - P3(exemplar はどの点に付くか): 成功の点にも付く。既定の
TraceBasedFilterは「サンプルされた span が ctx にあるか」だけを見て、失敗かどうかは見ない。今日は全部サンプルする設定(SDK の既定 ParentBased(AlwaysSample))なので、8 場面すべてに付いた。本番で比率サンプリングにすると、サンプルされなかったリクエストの点には付かない(未実測)
3. スタブと変異(-race 付き)
Edge・Traced を素通し、LogHandler を何もしない、SLIFrom を 0 にしたスタブでは 11 本中 10 本が落ちる。O9(クライアントに届くもの)は Recover と Adapt が既に正しいので素通り。
| 変異 | 検出したテスト |
|---|---|
| M1 Edge が投げ直さない | O8, O9 |
| M2 S7 で 499 を書かない | O2 |
| M3 S7 を span 属性で 499 にしようとする | O2(span は 200 のまま) |
| M4 otelhttp にも本物の MeterProvider | O1, O5, O6, O10 |
| M5 aborted で span を Error にしない | O2, O8 |
| M6 aborted で span に status_code を書かない | O2 |
| M7 span に error.type を書かない | O2 |
| M8 status 0 でも status_code を付ける | O8 |
| M9 4xx にも error.type | O1, O2, O6 |
| M10 LogHandler が trace_id を足さない | O3, O7, O11 |
M11 ログを context.Background() で書く | O3, O4, O7, O11 |
| M12 X-Request-Id を検査せず引き継ぐ | O4 |
| M13 長さの上限が 1 つずれる(65 まで) | O4 |
| M14 応答ヘッダに X-Request-Id を返さない | O3, O4 |
| M15 SLI の分母に 499 を入れる | O6 |
| M16 SLI が status≥500 だけを失敗に数える | O6 |
M17 メトリクスを context.Background() で記録 | O5 |
| M18 未知のメソッドを _OTHER にまとめない | O10(最初の O1〜O9 では生存。O10 を足して検出) |
| M19 Edge を otelhttp の外に置く | O2, O3, O5, O7, O11 |
**M20 LogHandler.WithAttrs が包みを外す** | O11(最初の O1〜O9 では生存。O11 を足して検出) |
| M21 aborted でも 0 を 200 に直す(Day 071 の R8 の挙動) | O8 |
- 21 通りすべて検出。最初の 9 本では M18・M20 が生き残り、M1 は O8 だけで検出していた。O9〜O11 を足した
- M17(メトリクスを ctx なしで記録)を見張るのは O5 だけ。点の数も属性も正しいまま、exemplar だけが消える。グラフからトレースへ飛べなくなるが、ダッシュボードの見た目は変わらない。気づきにくい壊れ方
4. 費用(割り当ては決定的、時間は参考)
成功 1 件(httptest.NewRecorder、ログは io.Discard、トレースは SDK の TracerProvider(処理器なし)、メトリクスは ManualReader):
B/op allocs/op
Day 071 の Stack(標準ライブラリだけ) 1585 17
今日の Stack(OTel は noop) 4204 48 ← otelhttp の包み(httpsnoop・body の包み・Labeler)と LogHandler
今日の Stack(OTel SDK) 7996 59 ← span の記録と 1 点の集計
案 C: otelhttp だけ(SDK・メトリクスも) 5490 41 ← 参考。S5・S6 が消える構成
二重計上(M4 の構成、SDK) 7996 59 ← Edge と同じ。集計は定常状態で割り当て 0
- Day 071 から +6,411 B・+42 allocs。うち +2,619 B・+31 allocs は OTel を noop にしても残る(otelhttp の包みとログの鍵)
- 二重計上(M4)は割り当てが増えない。費用では気づけず、O1 のような数のテストでしか見つからない
- 時間は今日の Stack(SDK)12〜21 µs、noop 9〜10 µs、Day 071 2.3〜3.0 µs だったが、計測中のロードアベレージが 17〜18(M1 8GB)なので比較に使わない
- ログの量(導出): 成功の 1 行は 266 バイト(実測。Day 071 は 165 バイト。trace_id 32 桁・span_id 16 桁・request_id 16 桁と鍵名で +101 バイト)。1,000 rps(仮定)なら成功だけで 266 × 1,000 × 86,400 ≈ 23.0 GB/日(Day 071 の 14.3 GB/日から +61%)
⚖️ 迷った他案と採らなかった理由
| 論点 | 採った案 | 迷った他案と採らなかった理由 | 前提が変わったら |
|---|---|---|---|
| メトリクスの分類の持ち方 | **semconv の status_code+error.type**(class は属性にしない) | **Day 071 の class 属性(5 値)をそのまま足す**: status_code と error.type から一意に決まるので重複。semconv に無い属性は既製のダッシュボードに出てこない | 499 と aborted を区別しない既製ダッシュボードしか無いなら、class を足しても系列は 5 倍にならない(status_code と 1 対 1)ので、足してよい |
| S7 の 499 を span に載せる方法 | **ow.WriteHeader(499) を実際に呼ぶ** | span 属性で上書き: otelhttp に後から 200 で上書きされる(M3 で実測)。otelhttp を fork して直す: 保守の費用。499 を諦めて span は 200 のまま: トレース画面で切断が成功に見える | 相手がまだ接続中なのに ctx が切れる構成(サーバー停止時の BaseContext の cancel など)では 499 が実際に届く。その構成を入れたら「相手がいない」を ctx 以外で判定する |
| otelhttp のメトリクス | **WithMeterProvider(noop) で止める** | otelhttp に任せて Edge は書かない: S5・S6 が消える(Day 071)。両方書く: 同じ名前のヒストグラムに 2 点入る(M4) | otelhttp が将来 defer でメトリクスを書くようになったら、Edge のメトリクスを外して otelhttp に戻す候補になる(O1〜O6 をそのまま流して確かめる) |
| error.type の値 | 5xx は番号の文字列、送信後の切断は aborted | **panic なら panic、error なら型名**(*net.OpError など): semconv も型名を例に挙げるが、ハンドラが返す error の型は増え続ける。**_OTHER に全部まとめる**: aborted と 5xx の区別が消える | エラー原因の内訳をメトリクスで見たいなら、固定の小さな表(db・upstream・panic)に写してから入れる |
| ログに trace_id を載せる場所 | slog.Handler で足す | Edge の 1 行にだけ直接書く: ハンドラが書いた行に付かない(O11)。otelslog の橋で OTel Logs に送る: 手元に無く未確認。今の出力先(JSON の標準出力)を変える判断が要る | ログを OTel Collector に集める構成に移ったら、otelslog を読んで比べる |
| request_id | 外の値を検査して引き継ぐ。だめなら作る | 常に作り直す: 上流のロードバランサのログとつなげない。trace_id で代用: trace_id は呼び出し元が traceparent で決められ、サービスの外から来る値をそのまま「自分の ID」とすることになる | 上流がすべて OTel で traceparent を送るようになったら、request_id は trace_id に寄せて 1 つにできる |
| method の大小文字 | そのまま比べる(get は _OTHER) | otelhttp と同じく大文字にしてから比べる(util.go 121 行): RFC 9110 ではメソッドは大小文字を区別する。net/http の ServeMux に GET /export を登録して get を送ると 405(2026-10-12 実測)。大文字にして数えると、405 で断った要求が GET の系列に混ざる | otelhttp のダッシュボードと数字を突き合わせる必要が出たら、大文字にする方に合わせる |
| exemplar | SDK の既定(TraceBasedFilter)のまま | 失敗の点だけに付ける独自フィルタ: 成功の点の exemplar は役に立ちにくいが、既定を変える根拠(費用の実測)が今は無い | exemplar の保存費用が問題になったら、OTEL_METRICS_EXEMPLAR_FILTER(config.go 195 行)で切り替えを測る |
🧭 設計思想・なぜこう書くのか
- 小さいインターフェースが差し替えを安くする: Edge が受け取るのは
metric.MeterProvider・trace.TracerProvider・*slog.Loggerという外の型だけです。テストでは SDK の ManualReader と SpanRecorder、本番では OTLP のエクスポーター、ベンチマークでは noop。Edge の中身は 1 行も変わりません - ctx を全部の出口に同じように渡す: Go の OTel は「今の span」を
context.Contextで運びます。Java の ThreadLocal のように暗黙ではないので、r.Context()を渡し忘れると(M11・M17)静かに鍵が消えます。今日の変異のうち 2 つがこの形でした - 「書く場所が 1 か所」を守るために、他の部品の記録を止める: Day 070 は「error は 1 回だけ扱う」、Day 071 は「出口は Edge が 1 回だけ」。今日は外の部品(otelhttp)のメトリクスも止めました。1 か所に寄せるには、他の場所を明示的に黙らせる必要があります
🌐 他言語との比較
| 言語・FW | ログに trace_id を載せる方法 | 送信後の切断の扱い | 今日の Go との違い |
|---|---|---|---|
| Go(今日) | slog.Handler で ctx から取る | Edge が defer で recover して span・メトリクスに書く | ctx を手で渡す。渡し忘れると静かに消える |
| Java(OTel Java agent+Logback) | エージェントが MDC に trace_id を入れる(記憶) | サーブレットの例外として計測される(記憶) | コードを書かずに付くが、非同期処理で MDC が引き継がれない問題がある(記憶) |
| Python(opentelemetry-instrumentation-logging) | logging の Record に otelTraceID を足す(記憶) | — | 暗黙の contextvars で伝わる |
| Node(@opentelemetry/instrumentation-pino) | pino の行に trace_id を足す(記憶) | 応答の "close" と "finish" で分かれる(記憶) | AsyncLocalStorage で暗黙に伝わる |
(Java・Python・Node の行は今回ソースも実行も確認していない)
🏭 実務での使いどころ
- otelhttp を入れるレビュー:
otelhttp.NewHandlerの行を見たら、WithMeterProviderが何かを確かめる。自前の集計もあるなら二重計上(M4)。割り当ても時間も増えないので、数のテストでしか気づけない - ストリーミング応答(CSV・JSON Lines・SSE)があるサービス: span の状態と status_code が S5・S6 で空にならないかを、今日の O2 のようなテストで固定する
- アラートからの調査:
error.type="aborted"の点の exemplar から trace に飛び、trace_id でログを 1 行引く。3 つの出口が同じ trace_id でつながっていることが前提 - 外部から来るヘッダ:
X-Request-Id・traceparentは利用者が書ける値。長さと文字種を見てからログに入れる
⚠️ よくある誤解・ミス
| 誤解・ミス | なぜ起こるか | 正しい理解 |
|---|---|---|
| span の属性は内側で上書きすれば直る | 内側が後に動くと思う | otelhttp は内側が戻った後に書く。SDK は後勝ちなので、内側の上書きは消える(M3) |
| otelhttp を入れたら自前の集計は消してよい | 最外側なら全部見えると思う | 送信後の切断はメトリクスから消える(Day 071)。消すなら otelhttp の側 |
| slog.Info でも trace_id は付く | Handler が足すので | ctx を渡さない slog.Info には付かない。InfoContext(r.Context(), …) を使う |
| Handler を包めば With したロガーにも効く | 包んだのは 1 回なので | WithAttrs・WithGroup が包み直さないと、With の先は素の Handler になる(M20) |
| status_code が 0 なら 200 と書けばよい | net/http の既定が 200 | 何も送らずに切った要求(O8)は「0 番」でも「200」でもない。属性ごと付けない |
| exemplar は失敗にだけ付く | 調べたいのは失敗なので | 既定の TraceBasedFilter はサンプルされたかだけを見る。成功にも付く |
| X-Request-Id はそのままログへ | ID だから安全と思う | 利用者が自由に書ける。長さと文字種を見る(O4) |
🚧 扱わなかった範囲と理由
| 範囲 | 理由 |
|---|---|
| 本物のエクスポーター(OTLP で Collector へ送る) | 今日は SDK の ManualReader と SpanRecorder で中身を確かめた。送信の費用・失敗時の挙動は未測定 |
外から来る traceparent の引き継ぎ(propagator の設定) | otelhttp の既定は otel.GetTextMapPropagator()(未設定なら何もしない)。上流とつなぐ構成は次回の候補 |
| 比率サンプリング | 全部サンプルする既定のまま。サンプルされない要求ではログの trace_id はあるがトレースが無く、exemplar も付かない(未実測) |
| S7 を実サーバーで再現する(本当に接続を切る) | Day 071 と同じく、切れた ctx で直接呼んだ。ow.WriteHeader(499) が切れた接続で何も起こさないことは実サーバーで確かめていない |
| otelslog の橋 | 手元のモジュールキャッシュに無い |
| HTTP/2 | Day 069〜071 と同じく未測定 |
| ヒストグラムのバケット境界の見直し | semconv の既定(0.005〜10 秒)のまま。CSV の大きな出力は 10 秒を超えうる |
| 時間の比較 | ロードアベレージ 17〜18。割り当てだけを根拠にした |
| Java・Python・Node の行 | 「記憶」と書いた。確認していない |
➡️ 次のステップ
- 発展: 上流から来る
traceparentを引き継ぐ(otel.SetTextMapPropagator(propagation.TraceContext{}))と、ログの trace_id が上流のログと一致することをテストにする。外から来た trace_id を信じてよいか(WithPublicEndpointFnで新しい root にする場合)も決める - 次回予告: 同テーマで「デバッグ」——OTel 接続でよく起きるバグ。propagator 未設定でトレースが途切れる、
slog.Info(ctx なし)で trace_id が消える、WithGroupで trace_id がグループの中に入る、比率サンプリングで exemplar が消える、otelhttp の Filter で除外したルートが Edge のメトリクスにだけ出る