请求链路可观测性：用 RequestID 串起访问日志与业务错误

线上一个 500，用户只说「刚才保存失败了」。访问日志里有 path 和状态码，错误日志里有一句「request failed」，但没有任何字段能把两条记录对上。这篇讲这个博客后端怎么用 requestId 把中间件、访问日志、业务错误和 panic 连成一条链路，以及几个反直觉的边界。

1. 排障失败，往往不是日志不够，而是对不上

真实场景：管理端保存文章返回 500。手上有三处线索：

访问日志：POST /api/admin/articles，500，耗时 87ms；
错误日志：request failed，带一个 error 字段；
网关日志：同样的 path，同样的时间。

问题在于「同样的时间」只是秒级近似。并发下同时有两三个保存请求，日志交错，靠时间戳分不清哪条错误属于哪个请求。访问日志只有状态码和耗时，错误日志只有一句 message 加一个 error，两份记录之间没有任何公共字段，这才是排障真正卡住的地方。

要定位，必须有一个请求级唯一标识，从入口一路带到最内层。这就是 requestId 的用处。但「生成一个 ID」是最不值钱的部分，真正的工作量在：让它进 ctx、进 logger、进响应头，并且保证只进一次——重复字段会让严格的日志管道直接丢弃整条记录。

2. 中间件顺序：requestId 必须比日志更靠外

internal/server/http.go 里的注册顺序是：

middleware.RequestID
customMiddleware.RequestID
middleware.RealIP
customMiddleware.WithClientInfo
customMiddleware.CaptureRequestBody
customMiddleware.Logger
middleware.Recoverer
customMiddleware.TimeoutExcept
customMiddleware.CORS
customMiddleware.SecurityHeaders

三条约束：

RequestID 必须在 Logger 之前。访问日志的 requestId 是从 ctx 里读的，顺序反了就只能记空字符串，而且不会报错——空字段是最难发现的故障。
RealIP 必须在 ClientInfo 之前。登录失败计数按 IP 限流，拿不到真实 IP 等于没限流。
Logger 必须在 Recoverer 外层。panic 被 Recoverer 接住后正常返回，Logger 才有机会补上那条 status=500 的访问日志；顺序反了，panic 请求会在访问日志里直接消失。

第二条是安全属性，第一条是排障属性。中间件顺序从来不是风格问题，它是「哪个中间件能看到什么」的声明。

3. requestId 注入：一次写入，三处生效

chi 自带 middleware.RequestID，但它只把 ID 放进 chi 自己的 context key，业务代码没有稳定入口。项目加了一层很薄的包装：

func RequestID(l *logger.Logger) func(next http.Handler) http.Handler {
	base := zap.NewNop()
	if l != nil && l.Logger != nil {
		base = l.Logger
	}
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			id := chimw.GetReqID(r.Context())
			if id == "" { // 没有 ID 就放行，不阻断请求
				next.ServeHTTP(w, r)
				return
			}
			// 响应头必须在 handler 写响应体之前设置。
			w.Header().Set(chimw.RequestIDHeader, id)

			ctx := context.WithValue(r.Context(), requestIDKey{}, id)
			ctx = logger.WithContext(ctx, &logger.Logger{
				Logger: base.With(zap.String("requestId", id)),
			})
			next.ServeHTTP(w, r.WithContext(ctx))
		})
	}
}

四个关键点：

响应头先写。handler 一旦开始写响应体，Header 就只能被忽略。X-Request-Id 因此对客户端可见，前端报错时可以把 ID 一起报回来。
私有 key 类型。不直接暴露 chi 的 key，业务侧统一走 RequestIDFrom(ctx)，换实现不用改调用点。
派生而非新建。base.With(...) 保留输出目标、caller、日志级别，只多一个字段；新建一个 zap.NewProduction() 会让请求日志绕开全局配置。
拿不到 ID 就放行。中间件被单独测试或复用时不该炸。

这里有个容易过度设计的点：不要用业务 ID（比如 articleId）代替 requestId。一个请求可能操作多条数据，也可能一条都不操作；requestId 的唯一职责是标识「这一次调用」。

4. ctx logger：让每一层都不再依赖全局变量

func WithContext(ctx context.Context, l *Logger) context.Context {
	if l == nil {
		return ctx
	}
	return context.WithValue(ctx, logCtxKey, l)
}

func From(ctx context.Context) *Logger {
	if ctx != nil {
		if l, ok := ctx.Value(logCtxKey).(*Logger); ok && l != nil {
			return l
		}
	}
	return nop // 未装配时也不返回 nil
}

From 永不返回 nil，没装配时给 no-op 实例。这个设计很实用：调用点不需要判空，漏装配的后果是「日志不输出」，而不是一次 panic。

于是 controller、service、dao 都可以直接 logger.From(ctx).Error(...)，日志天然带上 requestId，不用每一层手工传参；MapError 就是这么做的。代价是 logger 成了 ctx 的隐式依赖，测试时要显式塞一个进去。

5. 访问日志：字段固定，才好聚合

l.Info("http request",
	zap.String("requestId", RequestIDFrom(r.Context())),
	zap.String("method", r.Method),
	zap.String("path", r.Host+r.URL.Path),
	zap.Int("status", ww.Status()),
	zap.Int("size", ww.BytesWritten()),
	zap.Duration("time", time.Since(start)),
)

log.encoding: json 时的输出（节选）：

{"level":"info","msg":"http request","requestId":"<request-id>","status":500,"time":0.087}

设计取舍：

msg 固定为 http request，字段才是查询维度。message 里拼变量，聚合时就要写正则。
用 chi 的 WrapResponseWriter 拿真实状态码与字节数，ResponseWriter 本身不暴露这两个值。
请求体不进访问日志。管理端写请求体由 CaptureRequestBody 单独缓存给审计用，有体积上限。
现状字段里没有 userId，身份要从操作日志或鉴权日志反查；设计文档要求补上，还没做。

访问日志是唯一能回答「这个接口现在多慢、错误率多少」的数据源，所以字段一旦定下来就不要随意改名。改名等于让历史数据的聚合全部失效。

状态码本身也有失真的时候：客户端断开连接时服务端可能看不到 499，超时中间件补的 504 也可能被已经写出的 200 覆盖。所以 status 只能当参考，真正的失败原因还得回到错误日志里找。

6. MapError：完整错误只进日志，对外只有 500

func MapError(ctx context.Context, err error, notFound *CustomError, fields ...zap.Field) error {
	switch {
	case err == nil:
		return nil
	case errors.Is(err, gorm.ErrRecordNotFound):
		if notFound != nil {
			return notFound
		}
		return ErrNotFound
	case errors.As(err, new(*CustomError)):
		return err
	default:
		logger.From(ctx).Error("request failed",
			append([]zap.Field{zap.Error(err)}, fields...)...)
		return ErrInternalServerError
	}
}

三个分支对应三种对外承诺：记录不存在 → 404 + 领域业务码；已知领域错误 → 原样透出（比如 409 slug 冲突）；其余 → 记完整错误链，只返回 ErrInternalServerError。

这里的核心原则是：对外的错误信息是承诺，对内的错误信息是证据，两者不该共用同一个字符串。把 sql: no rows in result set 或连接串直接透给前端，既是安全问题，也会把内部实现钉死成对外契约。

fields 是业务定位信息，比如 zap.Uint("articleId", id)。这类字段比堆栈有用：堆栈只说哪一行，字段说哪条数据。

有个刻意的细节：这里不再手动加 requestId。ctx logger 已经带了，重复追加会在 JSON 里出现两个同名 key，严格的日志管道（部分 ES / Loki 摄入配置）会报错或只保留一个。

另一处取舍是 4xx 不记 error。404 是业务预期，不是系统故障；error 日志噪声一起来，真正的问题就被淹没。代价是「某个接口 404 突然变多」这类信号只能靠访问日志的 status 分布发现。

7. 一条链路是怎么被串起来的

线上排障的实际顺序：

用户报错，前端把响应头里的 X-Request-Id 带回来，或从访问日志按时间找到那条 500；
用这个 ID 检索访问日志，确认 path、状态码、耗时；
用同一个 ID 检索错误日志，拿到完整 error 与业务字段。

grep '"requestId":"<request-id>"' logs/server.log

日志进了 Loki / ES，就是一次按字段的等值查询：

{app="limit-blog"} | json | requestId="<request-id>"

能这样查的前提只有一个：两条日志的 requestId 来自同一个 ctx。中间件顺序错了，或业务层绕开 ctx 打日志，链路就断了。

这里有个当前实现的真实断点：service 里注入的 s.log 是构造时传入的全局 logger，不带 requestId，而 MapError 走的是 ctx logger。如果同一次失败在 service 里也记了一条（比如搜索失败），线上会看到两条日志：一条有 requestId，一条没有。做法要么统一改走 logger.From(ctx)，要么在构造 service 时就把 ctx logger 传下去，不要两套并存。

8. panic 与 SSE：两个必须特殊处理的地方

panic 的 500 不带信封，也不带 requestId。 项目用的是 chi 的 middleware.Recoverer，它的行为是打印 PrintPrettyStack 到 stderr，然后 WriteHeader(500)：

defer func() {
	if rvr := recover(); rvr != nil {
		// ... 上游 Upgrade 判断等
		PrintPrettyStack(rvr)
		w.WriteHeader(http.StatusInternalServerError)
	}
}()

两个后果：客户端拿到空响应体，不是 {code, message} 信封，前端统一错误处理会解析失败；堆栈走 stderr，不进 zap 的日志文件，也没有 requestId，容器里只收 stdout 时这条堆栈可能直接丢了。

正确做法是换成自己的 recover 中间件，用 logger.From(r.Context()).Error 加 zap.ByteString("stack", debug.Stack()) 记录，再返回统一信封。给 chi 的 Recoverer 提供 LogEntry 也行，但项目用的不是 chi 的 Logger，这条路走不通。

SSE 不能继承 30 秒请求超时。 站点构建状态是长连接，需要一个排除指定路径的包装：

timeoutHandler := middleware.Timeout(timeout)(next)
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	for _, path := range exceptPaths {
		if r.URL.Path == path {
			_ = http.NewResponseController(w).SetWriteDeadline(time.Time{})
			next.ServeHTTP(w, r)
			return
		}
	}
	timeoutHandler.ServeHTTP(w, r)
})

两个细节：路径是精确匹配，/api/admin/site/build/events 的子路径不会被排除；SetWriteDeadline(time.Time{}) 清掉服务端写超时，否则 30 秒后连接照样断开。

还有一层容易忽略：middleware.Timeout 是「事后」写 504——handler 返回后才检查 ctx.Err()。如果 handler 已经把 200 写出去了，504 会被忽略。所以超时真正生效的前提是查询层响应 ctx.Done()，而不是靠中间件兜底。

9. 脱敏：日志里最贵的错误是「写进去了」

管理端写操作会把请求体缓存下来给审计用，落库前必须脱敏：

var sensitiveKeys = map[string]bool{
	"password": true, "newpassword": true,
	"secretkey": true, "accesskey": true, "token": true,
	"refreshtoken": true, "authorization": true,
}

递归替换成 ***，键名统一转小写比较。两个边界：畸形 JSON 直接返回空串，不落原文——解析失败时最省事的做法就是别记；只处理对象与数组，标量原样返回。

请求体缓存本身还有体积上限（64 KB）和路径限制（仅 /api/admin/ 的写方法），multipart 直接跳过——上传文件不该被读进内存。脱敏函数对非 JSON 请求体一律返回空串，宁可少一条审计记录，也不落原文。

脱敏最容易被忽略的是「日志之外的副本」：错误对象可能带出 DSN，GORM 的 info 日志会打印带参数的 SQL，审计表还存了缓存下来的请求体。三处都该用同一套键名规则，只做一层，另外两层照样泄漏。

10. 边界与坑

requestId 不写进错误响应体。公开 API 返回内部 ID 没有收益，响应头里有就够了。
异步任务会丢 ctx。goroutine 里用 context.Background() 就断了链路，要把 requestId 显式传进去。
日志量。一次请求两条日志（访问 + 可能的错误）是基线，别在循环里打日志。
path 拼了 Host，跨环境对比要按路径前缀筛，否则 staging 与 prod 的聚合对不上。
no-op logger 让漏装配变得安静。好处是不 panic，坏处是排查「为什么没日志」时得先确认 ctx 里有没有 logger。
panic 的 500 与业务 500 形状不同，前端必须能处理空响应体。
超时是事后判定，缓存击穿、慢查询这类场景要自己在查询层埋 ctx.Done()。
日志轮转与保留期。本地用 lumberjack 按大小切割，容器里应同时输出到 stdout 交给采集端；两边都开而不设保留期，磁盘会被慢慢吃满。

11. 小结

可观测性不是「多打日志」，而是让同一次请求的所有记录共享一个键。这个项目里键是 requestId，路径是：chi 生成 → RequestID 中间件写响应头、ctx 与派生 logger → 各层 logger.From(ctx) → MapError 记录完整错误、对外只给 500 → 同一个 ID 检索两条日志。

剩下的都是细节：中间件顺序、不重复字段、panic 兜底、SSE 例外、敏感字段脱敏。这些细节不写，链路就是断的。

下一篇转到部署侧：单机 Docker Compose 里 Nginx 反代、HTTPS 与容器网络怎么配。

请求链路可观测性：用 RequestID 串起访问日志与业务错误

1. 排障失败，往往不是日志不够，而是对不上

2. 中间件顺序：requestId 必须比日志更靠外

3. requestId 注入：一次写入，三处生效

4. ctx logger：让每一层都不再依赖全局变量

5. 访问日志：字段固定，才好聚合

6. MapError：完整错误只进日志，对外只有 500

7. 一条链路是怎么被串起来的

8. panic 与 SSE：两个必须特殊处理的地方

9. 脱敏：日志里最贵的错误是「写进去了」

10. 边界与坑

11. 小结

Golang 后端

相关文章

自托管博客技术选型：Go + Astro + React 管理端

Go 服务端实战：用 Huma v2 把 OpenAPI 变成唯一契约

实战：从零做一个博客管理端页面

评论

留下评论