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

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

# 日志与链路追踪

## 概述

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

## 正文

### 自动埋点（OpenTelemetry）

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

```go
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 足够好，但有时候你需要更细粒度的控制，比如把某些字段打到自己的结构化日志系统里：

```go
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

```go
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，需要这样写：

```go
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 架构

```mermaid
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-元数据与鉴权]]