日志

cmd/server/main.go（启动时第一件事）

logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo}))
slog.SetDefault(logger)

请求中间件里绑定公共字段

公共字段只绑一次，后面的日志用这个 lg 打，不要每条手写同一组键。path 写路由模板而不是真实地址，否则按路由聚合时每条 id 都是一个新值。

lg := slog.Default().With(
	"request_id", requestID,
	"method", r.Method,
	"path", routePattern, // 例如 /notes/{id}，不是 /notes/12
)
lg.Info("request start")

defer func(start time.Time) {
	lg.Info("request done",
		"status", status,
		"duration_ms", time.Since(start).Milliseconds(),
		"user_id", userID,
		"scope_id", scopeID,
	)
}(time.Now())

测试里默认丢弃，需要断言时指向缓冲区

不要让人眼看终端来判断。需要断言那一行时，把处理程序指到 bytes.Buffer，再在缓冲里找消息。

// 大多数测试：丢弃日志，避免正常输出干扰断言
slog.SetDefault(slog.New(slog.NewTextHandler(io.Discard, nil)))

// 需要断言那一行时
var buf bytes.Buffer
slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, nil)))
// ... 触发越权请求
if !strings.Contains(buf.String(), "cross-scope access denied") {
	t.Fatalf("未记录越权警告：%s", buf.String())
}

必须在类型上拦截的敏感值

口令、令牌这类值若必须出现在某个结构里，让类型实现 LogValue，日志里就只出现改写后的值。没有这个方法时，在调用处就不要把该值传进 slog.Warn。

type sessionToken string

func (sessionToken) LogValue() slog.Value {
	return slog.StringValue("redacted")
}

越权警告（响应是 404，服务端另有这一行）

{"time":"2026-10-01T20:00:00+08:00","level":"WARN","msg":"cross-scope access denied","request_id":"01J9Z3K7QF8YV9M2N4P6R8T0W2","method":"GET","path":"/notes/{id}","status":404,"user_id":10,"resource_id":2,"user_scope_id":10,"resource_scope_id":20}

正常请求结束

{"time":"2026-10-01T20:00:00+08:00","level":"INFO","msg":"request done","request_id":"01J9Z3K7QF8YV9M2N4P6R8T0W2","method":"GET","path":"/notes/{id}","status":200,"duration_ms":12,"user_id":10,"scope_id":10}

场景一：用户报「打开某条笔记报了 404」

先问他要 X-Request-Id；他给不出来时，用 user_id 加时间窗，再找状态码 404 的那一行。

# 有 request_id
docker compose logs --no-log-prefix --since 2h api |
  jq -c 'select(.request_id=="01J9Z3K7QF8YV9M2N4P6R8T0W2")'

# 没有 request_id
docker compose logs --no-log-prefix --since 30m api |
  jq -c 'select(.user_id==10 and .status==404)'

判读一

看同一段日志里还有没有一条 WARN 的 cross-scope access denied，它决定这是两种 404 里的哪一种。

{"level":"WARN","msg":"cross-scope access denied","user_id":10,"resource_id":2,"user_scope_id":10,"resource_scope_id":20}
→ 记录属于别的所属范围。响应是有意做成 404 的，不用改代码。

{"level":"INFO","msg":"note not found","user_id":10,"resource_id":99999}
→ 这条 id 确实不存在。检查前端是不是在用旧链接。

场景二：越权警告突然变多

同一个用户在短时间内反复触发，是遍历 id 的特征，不是正常误操作。

docker compose logs --no-log-prefix --since 1h api |
  jq -r 'select(.msg=="cross-scope access denied") | .user_id' |
  sort | uniq -c | sort -rn | head

场景三：某个接口变慢

按 duration_ms 排序，取最慢的 20 条。判读时看它们是不是同一个 path：集中在一条路由上，说明问题在那个查询；分散在多个路由上，看是不是数据库或外部服务。

docker compose logs --no-log-prefix --since 30m api |
  jq -r 'select(.duration_ms > 200) | "\(.duration_ms)\t\(.path)\t\(.request_id)"' |
  sort -rn | head -20

场景四：错误变多，先看是哪一类

按 err 聚合。同一条错误占多数就顺着它查；分散且没有共同点，多半是上游依赖或数据库连接的问题。

docker compose logs --no-log-prefix --since 10m api |
  jq -r 'select(.level=="ERROR") | .err' |
  sort | uniq -c | sort -rn | head

场景五：确认记录链路本身没断

「查不到」也是一种结论。做过一次越权核对之后应当至少有一条警示；条数是 0 时，先怀疑日志配置，而不是怀疑没有越权发生。这条就是发布里那个回滚阈值。

docker compose logs --no-log-prefix --since 10m api |
  grep -c 'cross-scope access denied'

助手交出来的样子

log.Printf("查询笔记失败: %v", err)     ← 文本，没有 request_id
log.Info("req", "body", string(raw))    ← 整个请求体进了日志