cs-note/hhs/gRPC/5. 中间件与拦截器/16-日志与链路追踪.md

tags, create time

tags	create time
gRPC Logging Tracing OpenTelemetry Observability	2026-05-11 17:00

日志与链路追踪

概述

微服务的 observability 三支柱：Metrics、Logs、Traces。gRPC 生态已经为这三者提供了完善的工具链。不需要手写 logging interceptor——用成熟的库就行。但你需要理解这些库背后是怎么工作的，才能正确配置和调试。

正文

自动埋点（OpenTelemetry）

最简单且最可靠的方式是用官方 OTel SDK，一行代码搞定 span 创建、trace context propagation、RPC metrics 采集：

import (
	"go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc"
)

server := grpc.NewServer(
	grpc.StatsHandler(otelgrpc.NewServerHandler()),
)

conn, _ := grpc.Dial(addr, grpc.WithStatsHandler(otelgrpc.NewClientHandler()))

这是生产环境的首选方案。你只需引入包即可自动获得完整的分布式追踪能力。

[!tip] StatsHandler vs Interceptor OTel 内部使用 StatsHandler API，不是 Interceptor。这意味着它对业务逻辑零侵入、性能开销更低。这也是为什么推荐优先选 StatsHandler 做可观测性。

日志 Interceptor（手动实现）

虽然 OTel 足够好，但有时候你需要更细粒度的控制，比如把某些字段打到自己的结构化日志系统里：

func LoggingInterceptor(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
	start := time.Now()
	md, _ := metadata.FromIncomingContext(ctx)
	traceID := getTraceID(md)

	resp, err := handler(ctx, req) // 调用真正的业务 handler

	log.Info("rpc_complete",
		"method",      info.FullMethod,
		"duration_ms", time.Since(start).Milliseconds(),
		"error",       err,
		"trace_id",    traceID,
		"status_code", status.Code(err),
	)

	return resp, err
}

// getTraceID 从 metadata 中提取 trace ID
func getTraceID(md metadata.MD) string {
	tpp := md.Get("traceparent")
	if len(tpp) > 0 {
		return extractTraceID(tpp[0])
	}
	xid := md.Get("x-trace-id")
	if len(xid) > 0 {
		return xid[0]
	}
	return ulid.Make().String() // 无上游 trace，生成根 span
}

// extractTraceID 解析 W3C Trace Context 格式
func extractTraceID(traceParent string) string {
	parts := strings.Split(traceParent, "-")
	if len(parts) >= 2 {
		return parts[1]
	}
	return ""
}

这段代码展示了完整的 logging interceptor 模式——先提取 trace ID，调用 handler 后记录耗时和错误。getTraceID 的辅助逻辑做了三件事：优先解析 W3C traceparent；回退到 x-trace-id；不存在时生成新 root span。这样既能融入分布式链路，也能独立产生新链路。

[!question] 为什么在 handler 之后才打日志？ 因为我们需要知道请求的处理结果（耗时、错误）才能记录完整信息。如果在 handler 之前打日志，你只能拿到请求参数而拿不到响应。这也是 interceptor "洋葱模型"的核心优势——你可以包裹住 handler 的整个执行生命周期。这也正是 hhs/gRPC/5. 中间件与拦截器/14-Unary 与 Stream 拦截器 中强调的 chain 原理。

Trace ID 透传机制

gRPC 通过 metadata 传递 W3C Trace Context 标准格式——这是目前业界最通用的分布式追踪协议。Trace Context 由四个部分组成：

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             │   ───────────────────── ────────────────────── ──
             │        trace-id              span-id           flags
             │        (16 bytes)            (8 bytes)         (1 byte)
             └── version (00)

字段	长度	说明
version	2 hex chars	当前固定为 00
trace-id	32 hex chars	整个链路的唯一标识（所有 span 共享）
span-id	16 hex chars	当前操作的唯一标识
flags	2 hex chars	01 表示已采样，00 表示未采样

服务端读取上游 Trace ID

md, _ := metadata.FromIncomingContext(ctx)
traceParent := md.Get("traceparent")
var traceID string
if len(traceParent) > 0 {
    traceID = extractTraceID(traceParent[0]) // 见上节 helper
}
// traceID 为空 → 当前服务是链路起点，需要生成新 root span

客户端向下游注入 Trace ID

在使用 OpenTelemetry SDK 时，SDK 会自动完成 context propagation（详见本节开头的 otelgrpc），但如果你手动构造 metadata，需要这样写：

span := otel.Tracer("my-service").SpanContext()
ctx = metadata.AppendToOutgoingContext(
    ctx,
    "traceparent", fmt.Sprintf("00-%s-%s-01",
        span.TraceID().String(),
        span.SpanID().String(),
    ),
)

[!question] 为什么 OTel 不需要手写 traceparent？ OTel 的 StatsHandler 底层使用了 Go 的 stats.Handler API，它在 RPC 各个生命周期节点（如 InboundPayload, OutboundPayload）自动读写 metadata、创建 span。你只需要引入一个包，框架会帮你处理所有细节。这也是为什么官方强烈推荐使用自动埋点而非手动实现。

RPC Metrics 指标清单（OTel 自动产出）

Metric	Type	Labels	用途
rpc.server.duration	Histogram	method, service, status	服务端延迟分布，用于画 P95/P99
rpc.server.requests.count	Counter	method, service	服务端请求总量，监控流量趋势
rpc.server.responses.count	Counter	method, service, status	按状态码统计响应数，发现错误突增
rpc.client.duration	Histogram	method, service, status	客户端视角延迟，含网络 + 服务端总耗时
rpc.client.attempts.count	Counter	method, service	含重试的调用次数，>1 说明有重试发生

这些指标可以直接对接 Prometheus/Grafana，用于构建实时监控面板和告警规则。常见告警示例：

• SLO violation：rpc.server_duration{le="0.5"} / rpc_server_requests_count > 0.01 → P99 < 500ms 的 SLA 被击穿超过 1%
• 错误突增：increase(rpc_server_responses_count{status="Internal"}[5m]) > 10 → 5 分钟内 Internal 错误超 10 次

[!question] client duration vs server duration 为什么不同？ server duration 是服务端处理耗时，client duration 包含网络 RTT + 排队 + 服务端处理。如果 client duration >> server duration，说明问题出在网络或客户端侧（比如连接池太小导致排队），而不是服务端逻辑慢。这是排查性能问题的关键区分点。hhs/gRPC/5. 中间件与拦截器/14-Unary 与 Stream 拦截器 中的 Interceptor 也可以手动记录 server duration 来做对比验证。

端到端 Observability 架构

flowchart TB
    subgraph Client["客户端服务"]
        C1["App"] -->|"grpc.Dial WithStatsHandler"| C2["gRPC ClientConn"]
    end

    subgraph Network["网络层 Service Mesh / LB"]
        S1["Proxy Collect spans + traceparent"]
    end

    subgraph Server["服务端"]
        G1["gRPC Server"] -->|"otelgrpc StatsHandler"| O1["OTel SDK Create span"]
        O1 -->|"exporter"| E[("Tracing Backend")]
        O1 -->|"metrics"| P[("Metrics Backend")]
        D1["Interceptor Chain logging + trace_id"] -->|"structured log"| L[("Log Store")]
    end

    C2 -->|"HTTP/2 + traceparent metadata"| S1
    S1 -->|"forwarded + preserved traces"| G1
    G1 --> H["handler"]
    H --> D1

    style C2 fill:#00B6BC,color:#fff
    style G1 fill:#FFD43B
    style O1 fill:#EE5A24,color:#fff
    style S1 fill:#9B59B6,color:#fff

数据流说明：

1. 客户端通过 otelgrpc.NewClientHandler() 自动创建 client span，并将 traceparent 写入 metadata
2. 网络层（如 Envoy、Istio）可以采集 spans 并透传 trace context
3. 服务端的 otelgrpc.NewServerHandler() 提取 upstream trace ID，继续串联当前服务的 span
4. 自定义 Interceptor 从 metadata 中提取 traceID，将结构化日志发送到独立日志系统

[!tip] 为什么 Metrics 和 Traces 分开？ Metrics 回答"系统怎么样"（P99 延迟多少？错误率多少？），Traces 回答"哪里出问题"（哪个具体的请求链路慢了？）。二者互补——Grafana dashboard 用 metrics 发现异常，JAEGER/Tempo 用 traces 定位根因。

性能考量

• StatsHandler 比 Interceptor 性能更好——它通过 Go runtime channel 异步上报数据，不阻塞业务 goroutine
• 生产环境优先 StatsHandler + OTel，Interceptor 做附加层（如自定义日志格式）
• 不要每次都打印 full request/response（太吵），只在 debug level 或采样率下打印
• OTel SDK 默认使用 BatchSpanProcessor，会将 spans 批量导出。调整 ScheduleDelayMillis 和 ExportTimeoutMillis 可以权衡延迟与吞吐量

[!warning] 日志采样 全量打印每条 RPC 的详细信息会迅速压垮日志系统。建议对 INFO 级别做采样（如每秒 1%），DEBUG 级别仅在开发环境开启。对于 Trace ID，即使是采样的日志也必须带上——否则无法在日志系统中将分散的采样日志聚合到同一条链路。

最佳实践 Checklist

• StatsHandler 优先 — 可观测性用 OTel StatsHandler，不需要手写 interceptor
• Trace Context 遵循 W3C 标准 — 统一使用 traceparent key，避免各团队自定 header
• 结构化日志带 trace_id — 即使做了采样，也要保证每条日志可追溯到对应链路
• Root span 生成新 trace ID — 服务作为链路起点时，自动生成新 trace ID 而非留空
• Context Key 防冲突 — 见 hhs/gRPC/5. 中间件与拦截器/15-元数据与鉴权 的 context key 规范
• Interceptor Chain 分层 — 外层做 auth，内层做 logging（见 hhs/gRPC/5. 中间件与拦截器/14-Unary 与 Stream 拦截器 的 chain 原理）
• Metrics 对接 Grafana — 利用 OTel 产出的标准 metrics，快速搭建 dashboard
• gRPCurl 注入 traceparent 验证 — 排查 tracing 问题时，手动注入已知 trace ID 验证透传链路
• 区分 client/server duration — client 视角包含网络 RTT，server 视角只含处理时间
• 控制 metadata 大小 — 每个 traceparent 约 70 bytes，大量 metadata 累计可观，注意默认 8KB 限制

关联笔记

• hhs/gRPC/5. 中间件与拦截器/14-Unary 与 Stream 拦截器
• hhs/gRPC/5. 中间件与拦截器/15-元数据与鉴权