218 lines
10 KiB
Markdown
218 lines
10 KiB
Markdown
---
|
||
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-元数据与鉴权]]
|