observability — 日志、指标与链路

pkg/core/obs 把三件事装在一起：slog JSON 日志、Prometheus 指标、 OpenTelemetry 链路。这个示例让一个请求同时留下三种痕迹——一条带相关 id 的日志、一次自定义计数器的自增、以及（开启 tracing 时）一个能与调用方对齐的 span。看完你会知道相关 id 从哪来、指标该在哪个生命周期方法里注册。

运行

go run ./examples/observability

# 相关 id：不传就自动生成，传了就透传（响应头也会回写）
curl -i -H 'X-Request-ID: demo-1' localhost:8080/api/v1/work/alice

# 看日志（stdout）里的 service / trace_id / 字段
go run ./examples/observability 2>&1 | grep '"trace_id"'

# 看指标
curl -s localhost:8080/metrics | grep -E '^(observe_|http_server_)'

# 看链路（先把 config.yaml 的 trace.enabled 改成 true）
curl -i -H 'traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01' \
  localhost:8080/api/v1/work/alice

没有外部依赖，不需要 make dev。监听 :8080， -conf 默认指向 examples/observability/config.yaml。该文件里 trace.enabled 默认是 false，所以开箱即跑时链路是关闭的。

它演示了什么

结构化日志：obs.Init 由 verticle.Run 调用，JSON 输出到 stdout，每行都带 "service"。
相关 id 跟着 ctx 走：日志一律用 obs.Info(ctx, …)，不用自己传 logger。
相关 id 的三种来源：开 tracing 时是当前 span 的 trace id；否则是入站 X-Request-ID；都没有则生成一个。
相关 id 会写回响应体：obs.TraceID(ctx) 直接放进 data.trace_id。
自定义指标在 Setup 注册：env.Metrics 在 Setup 之前就已就绪，和 GET /metrics 共用同一个 registry。
子 span 无条件写：obs.StartSpan 在 tracing 关闭时是 no-op，所以不需要 if tracing 分支。

注册指标与请求处理

这段来自 examples/observability/main.go。Setup 里注册了两个自定义 collector，handler 里更新它们，并把 obs.TraceID(ctx) 一起返回——这样一次 curl 就能同时看到日志、指标与链路三个视角。

// Setup registers the custom metrics. env.Metrics is created before Setup
// (and the same registry backs GET /metrics), so a service can declare its
// own collectors here.
func (s *obsService) Setup(ctx context.Context, env *verticle.Env) error {
	if err := env.DecodeService(&s.cfg); err != nil {
		return err
	}
	s.work = env.Metrics.Counter("observe_work_total", "processed calls", "name")
	s.value = env.Metrics.Gauge("observe_last_value", "last computed value", "name")
	obs.Info(ctx, "custom metrics registered", "prefix", s.cfg.Prefix)
	return nil
}

func (s *obsService) workHandler(ctx context.Context, r *http.Request) (any, error) {
	name := r.PathValue("name")
	start := time.Now()

	// ctx carries the correlation id injected by httpx, so every line is
	// correlatable; no need to pass a logger around.
	obs.Info(ctx, s.cfg.Prefix+" started", "name", name)

	value := s.compute(ctx, name)

	s.work.WithLabelValues(name).Inc()
	s.value.WithLabelValues(name).Set(float64(value))

	obs.Info(ctx, s.cfg.Prefix+" done",
		"name", name, "value", value, "dur_ms", time.Since(start).Milliseconds())

	return map[string]any{
		"name":     name,
		"value":    value,
		"trace_id": obs.TraceID(ctx),
	}, nil
}

把耗时的部分包进自己的 span

同一份文件里的 compute。注意 obs.StartSpan 那句：它无条件写着，关闭 tracing 时整个函数退化成直接调用，日志照常输出。

// compute wraps the expensive step in its own span, nested under the
// request's server span. obs.StartSpan is a no-op when tracing is off, so
// the instrumentation stays unconditional — no `if tracing` branches.
func (s *obsService) compute(ctx context.Context, name string) int {
	ctx, span := obs.StartSpan(ctx, "compute")
	defer span.End()

	time.Sleep(5 * time.Millisecond)
	obs.Debug(ctx, "computed", "name", name)
	return len(name) * 2
}

一次请求留下的三种痕迹

flowchart LR
    C([客户端]) -->|"X-Request-ID 或 traceparent"| H["httpx wrapper
构造请求 ctx"]
    H --> S["server span
GET /api/v1/work/{name}"]
    S --> L["obs.Info(ctx, …)
→ slog JSON，带 trace_id"]
    S --> M["env.Metrics
→ Prometheus registry"]
    S --> T["obs.StartSpan(ctx, 'compute')
→ 嵌套子 span"]
    M --> EP["GET /metrics"]
    T --> EX["OTLP exporter
（trace.enabled 时）"]
    L --> STDOUT["stdout"]
    classDef off fill:#f4f4f4,stroke:#888,color:#2b2722
    class EX,EP off

日志、指标、链路三条路都从同一个请求 ctx 出发，因此能靠相关 id 对上。灰色两个出口由配置决定：/metrics 由 verticle 在注入 metrics 后自动注册，OTLP 导出只在 trace.enabled: true 时发生。

相关 id 的取值优先级是：当前 span 的 trace id（32 位 hex，跨服务唯一） → 入站的 X-Request-ID → 生成一个 8 字节 hex。结果写回响应头 X-Request-ID 并塞进 ctx，之后所有 obs.*(ctx, …) 都带它。开了 tracing 时，span 名用路由模板（GET /api/v1/work/{name}）而不是原始路径——每个 URL 一个 span 名会把后端打爆。

验证

curl -i -H 'X-Request-ID: demo-1' localhost:8080/api/v1/work/alice

{
  "code": 0,
  "msg": "ok",
  "data": { "name": "alice", "trace_id": "demo-1", "value": 10 }
}

value 是 len("alice") * 2 = 10； trace_id 回显了传进去的 X-Request-ID，响应头 X-Request-ID 也是 demo-1。同时 stdout 会打印：

{"time":"…","level":"INFO","msg":"work started","service":"observe","trace_id":"demo-1","name":"alice"}
{"time":"…","level":"DEBUG","msg":"computed","service":"observe","trace_id":"demo-1","name":"alice"}
{"time":"…","level":"INFO","msg":"work done","service":"observe","trace_id":"demo-1","name":"alice","value":10,"dur_ms":5}

指标端点上，自定义指标与框架指标并列出现：

curl -s localhost:8080/metrics | grep -E '^(observe_|http_server_)'
# observe_work_total{name="alice"} 1
# observe_last_value{name="alice"} 10
# http_server_requests_total{code="200",method="GET",route="GET /api/v1/work/{name}"} 1
# http_server_request_duration_seconds_bucket{…}

打开 tracing（把 config.yaml 的 trace.enabled 改成 true）后带上 traceparent 请求，响应头 X-Request-ID 与 data.trace_id 都会变成链路里的 trace id； endpoint 留空时只生成 span、不外发，便于离线观察。

测试

main_test.go 断言的是：

TestWorkHandlerCarriesTraceID：用 obs.WithTraceID(req.Context(), "trace-1") 造一个 ctx 后，返回的 trace_id 是 trace-1，而 value 是 10。
TestCustomMetricsAreExported：调用一次 handler 后， registry 上有 observe_work_total，恰好 1 条 series，计数值为 1。
TestFrameworkMetricsExist：registry 上能找到 go_goroutines——Go collector 已注册。
TestTracingJoinsTheCallersTrace：用 obs.InitTracing(…, TraceConfig{Enabled: true}) 打开链路后，带 traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-… 的请求，响应头 X-Request-ID 是 4bf92f3577b34da6a3ce929d0e0e4736，响应体里也含这个 id。
TestTracingOffKeepsTheOldContract：默认（无 trace 段）时，入站的 traceparent 不会变成相关 id——关闭 tracing 的行为与接入前完全一致。

go test ./examples/observability

observability — 日志、指标与链路

运行

它演示了什么

注册指标与请求处理

把耗时的部分包进自己的 span

一次请求留下的三种痕迹

验证

测试

相关

相关示例