可观测性

pkg/core/obs 一次给齐三件事:结构化日志、Prometheus 指标、 OpenTelemetry 链路。日志默认开,指标随 /metrics 暴露,链路是 opt-in 且关掉时全部为 no-op。

日志:slog JSON 加一个相关 id

verticle.Run 启动时调用 obs.Init(name, level):JSON 写到 stdout,每条都带 "service" 字段。业务代码一律用带 ctx 的包级函数, 相关 id 会自动挂上,不需要传 logger:

func Init(service string, level string) error {
    var lv slog.Level
    if err := lv.UnmarshalText([]byte(level)); err != nil {
        lv = slog.LevelInfo
    }
    h := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: lv})
    slog.SetDefault(slog.New(h).With("service", service))
    return nil
}

func Debug(ctx context.Context, msg string, args ...any) { Log(ctx).Debug(msg, args...) }
func Info(ctx context.Context, msg string, args ...any)  { Log(ctx).Info(msg, args...) }
func Warn(ctx context.Context, msg string, args ...any)  { Log(ctx).Warn(msg, args...) }
func Error(ctx context.Context, msg string, args ...any) { Log(ctx).Error(msg, args...) }
obs.Info(ctx, "user created", "user_id", 123, "dur_ms", 12)
// {"time":"…","level":"INFO","msg":"user created","service":"demo","trace_id":"a1b2c3d4","user_id":123,"dur_ms":12}

obs.Log(ctx) 是"已经带上 trace_id 的 logger",要传给别的库时用它。 不要 fmt.Println 打日志,也不要自己 new logger。

trace_id 到底是谁 obs.TraceID(ctx) 先问当前 span:开了 tracing 就是 span 的 trace id (32 位 hex,能直接拿去追踪后端查);没有 span 就取 WithTraceID 塞进 ctx 的请求级 id。所以把 tracing 打开的那一刻,日志里的相关 id 自动升级为 trace id,调用点一行都不用改。

相关 id 的来源与优先级

httpx 的封套层按顺序取第一个可用的值,然后回写响应头 X-Request-ID:

顺序 来源 说明
1 入站 X-Request-ID 调用方自己带的关联 id,原样透传(便于跨系统对齐);超过 128 字节截断
2 当前 span 的 trace id 仅当 tracing 开启且入站未带 id
3 新生成的 8 字节 hex 两者都没有时兜底,保证日志一定可关联
// pkg/core/httpx/server.go
traceID := r.Header.Get("X-Request-ID")
if len(traceID) > maxTraceIDLen {
    // An oversized id would ride along in every log line.
    traceID = traceID[:maxTraceIDLen]   // = 128
}
if traceID == "" {
    traceID = obs.TraceID(spanCtx)
}
if traceID == "" {
    traceID = newTraceID()
}
w.Header().Set("X-Request-ID", traceID)
128 字节上限 客户端给的 id 不可信:一个 10 KB 的 X-Request-ID 会跟着这个请求产生的 每一条日志、每一个 span 属性走,把存储和带宽吃掉。W3C trace id 只有 32 个 hex 字符, 超过 128 字节的已经不是关联 id 了,直接截断。

请求的 ctx 与连接解耦,相关 id 在这一步注入。所以客户端断连不会污染 id,handler 也还能把副作用写完(记 499,详见 HTTP 与路由):

ctx, cancel := context.WithTimeout(
    context.WithoutCancel(obs.WithTraceID(spanCtx, traceID)), s.cfg.Timeout)
defer cancel()

Prometheus 指标

obs.NewMetrics() 建一个独立 registry,装 Go runtime / process 收集器 与两个框架指标,GET /metrics 用的就是这个 registry:

指标 类型 标签
http_server_requests_total counter route method code
http_server_request_duration_seconds histogram route method code
go_* / process_* runtime / 进程 —

route 取的是 http.Request.Pattern,即路由模板 (GET /api/v1/hello/{name})而不是原始路径——否则每个用户 id 都会 变成一个独立时间序列。code 来自封套层记录的状态码,客户端断开记 499。

自定义指标在 Setup 里注册。env.Metrics 在 Setup 之前就已就绪,且与 /metrics 共用同一个 registry:

func (s *obsService) Setup(ctx context.Context, env *verticle.Env) error {
    s.work = env.Metrics.Counter("observe_work_total", "processed calls", "name")
    s.value = env.Metrics.Gauge("observe_last_value", "last computed value", "name")
    return nil
}

// handler 里
s.work.WithLabelValues(name).Inc()
s.value.WithLabelValues(name).Set(float64(value))

Counter / Gauge / Histogram 三个方法签名与 prometheus 一致,Histogram 传空 buckets 表示用 prometheus.DefBuckets。 同名重复声明返回第一次的句柄(库与服务各自声明同一指标不会互相炸), 但同名声明成不同类型会 panic —— 这属于真 bug,应该启动就发现。

OpenTelemetry 链路

默认关闭。开关只有配置,代码不写分支:

trace:
  enabled: false
  # endpoint: "localhost:4317"   # OTLP/gRPC collector;留空则只生成 span 不外发
  # sample_ratio: 1.0            # 采样比例 0~1(0 = 全丢,1 = 全采)
  # export_timeout: 10s
配置键 tag 默认值 作用
trace.enabled false 总开关。关着时 InitTracing 清空 provider 与传播器,回到纯 X-Request-ID 行为
trace.endpoint 空(optional) OTLP/gRPC collector 地址,如 localhost:4317;留空则 span 只带 trace id 不上报
trace.insecure 空(optional) OTLP/gRPC 以明文拨号(集群内常见形态,TLS 交给 mesh)
trace.sample_ratio 1.0 头部采样比例;≥1 全采,≤0 全丢,中间值按 trace id 比例采
trace.export_timeout 10s 单批导出的上限;≤0 时在 InitTracing 里回填 10s

sampler 一律包一层 ParentBased:上游已经决定采样的链路始终保留, 否则追踪后端只会看到半条链——比没有更难用。开启后 Run 拿到一个 shutdown 函数,在优雅退出的排空阶段 flush 最后一批 span。

// 业务代码加子 span:关着的时候是 no-op span,不用写 if tracing 分支
ctx, span := obs.StartSpan(ctx, "compute")
defer span.End()

// 出站调用时把链路带出去(HTTP)
h := http.Header{}
obs.InjectHTTP(ctx, h)   // 写入 traceparent,下游服务续接同一条链路

HTTP 侧由封套层自动完成:obs.StartHTTPSpan 从请求头 extract 出 traceparent 续接调用方的链路,开一个 SpanKindServer 的 span, span 名与 http.route 都取路由模板(低基数),响应时 obs.EndHTTPSpan 记上 http.response.status_code 并结束。

关着的时候为什么不能 extract 没开 tracing 时 StartHTTPSpan 直接返回原 ctx 与 no-op span,不读 入站的 traceparent:读进来会往 ctx 里塞一个活的 SpanContext,把相关 id 劫持成对方的 trace id——而本进程根本没记录任何 span。这是"关掉 tracing 后行为与接入前完全一致" 的实现细节。

跨进程传播:三条通道都是自动的

通道 载体 接入方式 关闭时
HTTP 请求头(traceparent) httpx 封套层,业务零代码 no-op span,相关 id 回落 X-Request-ID
gRPC gRPC metadata 的 traceparent 服务端 unary / stream 拦截器 + 客户端 unary / stream 拦截器,New/Dial 时无条件装上 no-op tracer + no-op propagator
rpcx 请求 metadata(share.ReqMetaDataKey) 服务端 plugin(PreHandleRequest + PostCall)+ 客户端 XClient 包装 同上

obs.Extract / obs.Inject 接受任意 propagation.TextMapCarrier,gRPC 与 rpcx 各自用一个薄适配层把 metadata 包成 carrier,因此走的是同一套 W3C 传播器。rpcx 的 Failtry 重试会在同一个 client span 下重发,一次逻辑调用一个 span。

一个请求经过两个服务

sequenceDiagram
    autonumber
    participant C as 客户端
    participant A as 服务 A(http + 日志 + 指标)
    participant B as 服务 B
    participant O as OTLP collector
    C->>A: GET /api/v1/hello/world
traceparent / X-Request-ID A->>A: StartHTTPSpan:extract 出 trace id
开 server span(名=路由模板) A->>A: ctx 注入 trace id → 每条日志带 trace_id A->>A: obs.StartSpan("compute") 子 span A->>B: gRPC/rpcx:Inject 写 traceparent 到 metadata B->>B: 拦截器/plugin:Extract → 续接同一条链路 B-->>A: 返回(span 结束,状态码作属性) A->>A: EndHTTPSpan + 记 http_server_* 指标 A-->>C: 响应封套 + X-Request-ID 回写 A-->>O: 批量导出 span(bounded by export_timeout) B-->>O: 批量导出 span
一条 trace 穿过两个服务:跨进程靠 traceparent,进程内靠 ctx。 日志、指标、链路三者在服务 A 内是同一份请求上下文——所以日志里的 trace_id 能直接跳到追踪后端,指标里的 route 又能定位是哪条路由在变慢。

排障顺序

  1. 先看指标定位面:http_server_requests_total 按 route + code 找出是哪条路由的哪类状态码在涨。
  2. 再用相关 id 收窄:从客户端手上的响应头 X-Request-ID 或日志里的 trace_id,把这一个请求在所有服务的日志串起来。
  3. 最后用链路看因果:开了 tracing 时用 trace id 打开完整 span 树, 看时间花在哪一跳、哪一步。

相关示例