feat: 统一后端日志并记录接口请求

backend/DEPLOYMENT.md

@@ -22,6 +22,10 @@ API 启动时会在事务和数据库锁保护下应用尚未执行的版本迁
 
 生产 API 已在服务级配置共享日志平台使用的 Docker 标签：`observability.logs=true`、`observability.project=ballet-island`、`observability.service=api`、`observability.env=production`。后端使用 `slog` 将 JSON 日志输出到 stdout；Docker 使用 `json-file` 驱动，按 `max-size: "20m"`、`max-file: "5"` 轮转。这是容器本地日志轮转配置，Loki 的保留时间由共享平台单独管理。[Docker 日志轮转说明](https://docs.docker.com/engine/logging/drivers/json-file/)
 
+日志由 `internal/logging` 统一配置，入口使用 `slog.SetDefault(logging.New(os.Stdout))`。非请求日志继续使用 `slog`；处理请求时通过 `logging.FromContext(r.Context())` 获取带请求编号的 logger，业务代码只传入可公开的结构化字段，不记录原始数据库或网络错误。请求中间件在最外层路由接入一次，避免重复记录。
+
+每次请求完成输出一条 `http request completed`，包含 `request_id`、`method`、`route`、`status` 和 `duration_ms`；2xx/3xx 使用 INFO、4xx 使用 WARN、5xx 使用 ERROR。健康检查也会记录。`route` 是匹配的路由模板（例如 `GET /v1/records/{id}`），未匹配时为 `unmatched`；不记录实际路径参数、查询参数、请求头或请求体。`request_id` 由服务端生成并通过响应头 `X-Request-ID` 返回，客户端提供的同名头不会被采用；业务异常日志携带相同编号。请求因 panic 中断时输出 ERROR 级别的 `http request aborted`，保留已有响应状态，尚未发送响应则记为 `0`，仍由 Go HTTP 服务处理 panic。
+
 接入前提是 API 所在主机已有 Alloy，能够通过该主机的 Docker API 读取容器日志，按 `observability.logs=true` 发现容器，将其余三个标签映射为 Loki 的 `project`、`service`、`env`，并发送到可达的 Loki。`host` 标签由 Alloy 按实际主机设置。该采集方式不要求 API 加入日志平台网络或在业务镜像内安装 Alloy。本仓库只配置业务容器，Alloy、Loki 和 Grafana 由共享平台管理。[Alloy Docker 日志采集说明](https://grafana.com/docs/alloy/latest/reference/components/loki/loki.source.docker/)
 
 沿用上述发布流程，`docker compose up` 会重新创建配置发生变化的 API 容器以应用标签和日志驱动；仅执行 `restart` 不会应用这些变更。部署后在应用主机检查实际容器：
@@ -41,6 +45,14 @@ docker ps \
 
 核对查询结果包含本次部署产生的新启动日志，时间和主机正确，才算日志链路验收通过。容器健康或 Alloy/Loki 就绪不能代替此项验收。本配置仅接入 API 日志，外部 PostgreSQL 日志、主机指标和告警由各自部署单独配置。
 
+请求日志需要部署包含上述模块的新 API 镜像后生效。可在应用主机执行 `curl -i http://127.0.0.1:8113/healthz`，记下响应头 `X-Request-ID`，在 Grafana 中查询访问日志：
+
+```logql
+{project="ballet-island", service="api", env="production"} |= "http request completed"
+```
+
+再用 `{project="ballet-island", service="api", env="production"} |= "<X-Request-ID 的值>"` 查找同一次请求的全部日志，核对状态、耗时与请求编号。请求编号保留为 JSON 字段，无需改动现有容器采集标签。
+
 ## 验收与回退
 
 发布成功后，从服务器确认 `curl -f http://127.0.0.1:8113/readyz`，并从外部确认 HTTPS 域名的 `/readyz`。真实微信登录、合法域名及小程序构建产物仍需单独验收；`/readyz` 只证明 API 可连接数据库。

backend/cmd/server/main.go

@@ -14,11 +14,12 @@ import (
 	"ballet-island/backend/internal/database"
 	"ballet-island/backend/internal/httpapi"
 	"ballet-island/backend/internal/identity"
+	"ballet-island/backend/internal/logging"
 	"github.com/jackc/pgx/v5/pgxpool"
 )
 
 func main() {
-	slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, nil)))
+	slog.SetDefault(logging.New(os.Stdout))
 	if err := run(); err != nil {
 		slog.Error("server stopped", "error", err)
 		os.Exit(1)

backend/internal/httpapi/logging_test.go

@@ -0,0 +1,92 @@
+package httpapi_test
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"errors"
+	"log/slog"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"ballet-island/backend/internal/httpapi"
+	"ballet-island/backend/internal/logging"
+)
+
+type unavailableIdentity struct{}
+
+func (unavailableIdentity) Exchange(context.Context, string) (string, error) {
+	return "", errors.New("private-upstream-error")
+}
+
+func TestAppRequestLogs(t *testing.T) {
+	for _, tc := range []struct {
+		name, method, target, body, route, level string
+		status                                   int
+		businessError                            bool
+	}{
+		{"health", "GET", "/healthz", "", "GET /healthz", "INFO", 200, false},
+		{"unauthorized", "GET", "/v1/records/private-record-id?token=private-query", "", "GET /v1/records/{id}", "WARN", 401, false},
+		{"invalid login", "POST", "/v1/session", `{"code":"private-login-code","unexpected":true}`, "POST /v1/session", "WARN", 400, false},
+		{"unknown route", "GET", "/private-path?token=private-query", "", "unmatched", "WARN", 404, false},
+		{"upstream error", "POST", "/v1/session", `{"code":"private-login-code"}`, "POST /v1/session", "ERROR", 503, true},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			var output bytes.Buffer
+			previous := slog.Default()
+			slog.SetDefault(logging.New(&output))
+			t.Cleanup(func() { slog.SetDefault(previous) })
+			handler := httpapi.NewAppHandler(nil, unavailableIdentity{}, nil)
+			request := httptest.NewRequest(tc.method, tc.target, strings.NewReader(tc.body))
+			request.Header.Set("Authorization", "Bearer private-token")
+			request.Header.Set("X-Request-ID", "private-client-id")
+			response := httptest.NewRecorder()
+			handler.ServeHTTP(response, request)
+			if response.Code != tc.status {
+				t.Fatalf("response status = %d, want %d", response.Code, tc.status)
+			}
+
+			var records []map[string]any
+			for _, line := range strings.Split(strings.TrimSpace(output.String()), "\n") {
+				if line == "" {
+					continue
+				}
+				var record map[string]any
+				if err := json.Unmarshal([]byte(line), &record); err != nil {
+					t.Fatalf("invalid JSON log: %v", err)
+				}
+				records = append(records, record)
+			}
+			wantCount := 1
+			if tc.businessError {
+				wantCount++
+			}
+			if len(records) != wantCount {
+				t.Fatalf("log count = %d, want %d (one access log plus any business error)", len(records), wantCount)
+			}
+			access := records[len(records)-1]
+			for key, want := range map[string]any{
+				"msg": "http request completed", "method": tc.method, "route": tc.route,
+				"level": tc.level, "status": float64(tc.status),
+			} {
+				if access[key] != want {
+					t.Errorf("%s = %v, want %v", key, access[key], want)
+				}
+			}
+			requestID := response.Header().Get("X-Request-ID")
+			if requestID == "" || access["request_id"] != requestID {
+				t.Fatalf("response and access log must share a generated request ID: %v", access)
+			}
+			if duration, ok := access["duration_ms"].(float64); !ok || duration < 0 {
+				t.Errorf("invalid duration_ms: %v", access["duration_ms"])
+			}
+			if tc.businessError && (records[0]["request_id"] != requestID || records[0]["msg"] != "business request failed") {
+				t.Errorf("business error must share the request ID: %v", records[0])
+			}
+			if strings.Contains(output.String(), "private-") {
+				t.Fatalf("request or error secrets leaked into logs: %s", output.String())
+			}
+		})
+	}
+}

backend/internal/httpapi/practice.go

@@ -5,13 +5,13 @@ import (
 	"encoding/json"
 	"errors"
 	"io"
-	"log/slog"
 	"net/http"
 	"strconv"
 	"strings"
 	"time"
 
 	"ballet-island/backend/internal/identity"
+	"ballet-island/backend/internal/logging"
 	"ballet-island/backend/internal/practice"
 	"github.com/jackc/pgx/v5/pgxpool"
 )
@@ -45,7 +45,7 @@ func NewAppHandler(pool *pgxpool.Pool, verifier IdentityVerifier, now func() tim
 	mux.HandleFunc("PUT /v1/records/{id}", a.auth(a.saveRecord))
 	mux.HandleFunc("DELETE /v1/records/{id}", a.auth(a.deleteRecord))
 	mux.HandleFunc("GET /v1/review", a.auth(a.review))
-	return mux
+	return logging.AccessLog(mux)
 }
 
 func respond(w http.ResponseWriter, status int, value any) {
@@ -68,7 +68,7 @@ func decode(w http.ResponseWriter, r *http.Request, value any) error {
 	return nil
 }
 
-func failure(w http.ResponseWriter, err error) {
+func failure(w http.ResponseWriter, r *http.Request, err error) {
 	status, code, message := 503, "service_unavailable", "服务暂时不可用，请稍后重试"
 	switch {
 	case errors.Is(err, practice.ErrUnauthorized), errors.Is(err, identity.ErrInvalidCode):
@@ -85,7 +85,7 @@ func failure(w http.ResponseWriter, err error) {
 		status, code, message = 410, "record_deleted", practice.ErrDeleted.Error()
 	default:
 		// Do not log raw database/network errors: they may contain notes, credentials or URLs.
-		slog.Error("business request failed", "category", code)
+		logging.FromContext(r.Context()).ErrorContext(r.Context(), "business request failed", "category", code)
 	}
 	respond(w, status, map[string]any{"error": map[string]string{"code": code, "message": message}})
 }
@@ -97,7 +97,7 @@ func (a *app) auth(fn operation) http.HandlerFunc {
 		r = r.WithContext(ctx)
 		header := r.Header.Get("Authorization")
 		if !strings.HasPrefix(header, "Bearer ") {
-			failure(w, practice.ErrUnauthorized)
+			failure(w, r, practice.ErrUnauthorized)
 			return
 		}
 		user, err := a.store.Authenticate(ctx, strings.TrimPrefix(header, "Bearer "))
@@ -105,7 +105,7 @@ func (a *app) auth(fn operation) http.HandlerFunc {
 			err = fn(w, r, user)
 		}
 		if err != nil {
-			failure(w, err)
+			failure(w, r, err)
 		}
 	}
 }
@@ -117,17 +117,17 @@ func (a *app) login(w http.ResponseWriter, r *http.Request) {
 		Code string `json:"code"`
 	}
 	if err := decode(w, r, &input); err != nil || strings.TrimSpace(input.Code) == "" || len(input.Code) > 512 {
-		failure(w, practice.ErrInvalid)
+		failure(w, r, practice.ErrInvalid)
 		return
 	}
 	identity, err := a.verifier.Exchange(ctx, input.Code)
 	if err != nil {
-		failure(w, err)
+		failure(w, r, err)
 		return
 	}
 	session, err := a.store.Login(ctx, identity)
 	if err != nil {
-		failure(w, err)
+		failure(w, r, err)
 		return
 	}
 	respond(w, 200, session)

backend/internal/logging/http.go

@@ -0,0 +1,86 @@
+package logging
+
+import (
+	"context"
+	"crypto/rand"
+	"log/slog"
+	"net/http"
+	"time"
+)
+
+// AccessLog wraps the outermost router and logs every request, including health
+// checks and routing errors. It generates X-Request-ID instead of trusting a
+// client value. Only route patterns are logged: URLs, headers and bodies may
+// contain credentials or personal data. Panics propagate to net/http unchanged.
+func AccessLog(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		started := time.Now()
+		requestID := rand.Text()
+		logger := slog.Default().With("request_id", requestID, "method", r.Method)
+		r = r.WithContext(context.WithValue(r.Context(), contextKey{}, logger))
+		w.Header().Set("X-Request-ID", requestID)
+		response := &responseWriter{ResponseWriter: w}
+		completed := false
+		defer func() {
+			status := response.status
+			if status == 0 && completed {
+				status = http.StatusOK
+			}
+			level := slog.LevelInfo
+			if status >= 500 || !completed {
+				level = slog.LevelError
+			} else if status >= 400 {
+				level = slog.LevelWarn
+			}
+			message := "http request completed"
+			if !completed {
+				// An aborted response has no invented 500 status; zero means no
+				// final headers were sent. net/http retains its panic handling.
+				message = "http request aborted"
+			}
+			route := r.Pattern
+			if route == "" {
+				route = "unmatched"
+			}
+			logger.Log(r.Context(), level, message,
+				"route", route, "status", status,
+				"duration_ms", float64(time.Since(started))/float64(time.Millisecond))
+		}()
+		next.ServeHTTP(response, r)
+		completed = true
+	})
+}
+
+type responseWriter struct {
+	http.ResponseWriter
+	status int
+}
+
+func (w *responseWriter) WriteHeader(status int) {
+	w.ResponseWriter.WriteHeader(status)
+	// Informational headers can precede the final response. A protocol switch
+	// is final; later duplicate headers must not overwrite the actual status.
+	if w.status == 0 && (status >= 200 || status == http.StatusSwitchingProtocols) {
+		w.status = status
+	}
+}
+
+func (w *responseWriter) Write(data []byte) (int, error) {
+	if w.status == 0 {
+		w.status = http.StatusOK
+	}
+	// Let the underlying writer perform content-type detection and write errors.
+	return w.ResponseWriter.Write(data)
+}
+
+// Unwrap preserves optional operations through http.ResponseController.
+// Handlers should use that controller instead of asserting legacy interfaces.
+func (w *responseWriter) Unwrap() http.ResponseWriter { return w.ResponseWriter }
+
+func (w *responseWriter) FlushError() error {
+	err := http.NewResponseController(w.ResponseWriter).Flush()
+	if err == nil && w.status == 0 {
+		w.status = http.StatusOK
+	}
+	return err
+}

backend/internal/logging/http_test.go

@@ -0,0 +1,185 @@
+package logging_test
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"io"
+	"log"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"sync"
+	"testing"
+
+	"ballet-island/backend/internal/logging"
+)
+
+func captureLogs(t *testing.T) *bytes.Buffer {
+	t.Helper()
+	var output bytes.Buffer
+	previous := slog.Default()
+	slog.SetDefault(logging.New(&output))
+	t.Cleanup(func() { slog.SetDefault(previous) })
+	return &output
+}
+
+func readLogs(t *testing.T, output *bytes.Buffer) []map[string]any {
+	t.Helper()
+	var records []map[string]any
+	decoder := json.NewDecoder(output)
+	for {
+		var record map[string]any
+		err := decoder.Decode(&record)
+		if err == io.EOF {
+			return records
+		}
+		if err != nil {
+			t.Fatalf("decode log: %v", err)
+		}
+		records = append(records, record)
+	}
+}
+
+func TestAccessLogPreservesHTTPResponses(t *testing.T) {
+	for _, tc := range []struct {
+		name   string
+		serve  func(http.ResponseWriter, *http.Request)
+		status int
+		body   string
+	}{
+		{"implicit status", func(w http.ResponseWriter, _ *http.Request) { _, _ = io.WriteString(w, "ok") }, 200, "ok"},
+		{"empty response", func(http.ResponseWriter, *http.Request) {}, 200, ""},
+		{"explicit status", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(204) }, 204, ""},
+		{"duplicate headers", func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(201)
+			w.WriteHeader(503)
+		}, 201, ""},
+		{"informational headers", func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(http.StatusEarlyHints)
+			w.WriteHeader(202)
+		}, 202, ""},
+		{"flush commits status", func(w http.ResponseWriter, _ *http.Request) {
+			if err := http.NewResponseController(w).Flush(); err != nil {
+				t.Errorf("flush: %v", err)
+			}
+			w.WriteHeader(503)
+			_, _ = io.WriteString(w, "ok")
+		}, 200, "ok"},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			output := captureLogs(t)
+			// Use a real server: ResponseRecorder does not model 1xx headers.
+			server := httptest.NewUnstartedServer(logging.AccessLog(http.HandlerFunc(tc.serve)))
+			server.Config.ErrorLog = log.New(io.Discard, "", 0)
+			server.Start()
+			defer server.Close()
+			response, err := server.Client().Get(server.URL)
+			if err != nil {
+				t.Fatal(err)
+			}
+			body, err := io.ReadAll(response.Body)
+			response.Body.Close()
+			if err != nil {
+				t.Fatal(err)
+			}
+			server.Close() // Wait for the deferred access log before reading the buffer.
+			if response.StatusCode != tc.status || string(body) != tc.body {
+				t.Fatalf("response = %d %q, want %d %q", response.StatusCode, body, tc.status, tc.body)
+			}
+			if tc.body != "" && response.Header.Get("Content-Type") != "text/plain; charset=utf-8" && tc.name != "flush commits status" {
+				t.Errorf("content-type detection changed: %v", response.Header)
+			}
+			records := readLogs(t, output)
+			if len(records) != 1 || records[0]["status"] != float64(response.StatusCode) {
+				t.Fatalf("log status must match the response: %v", records)
+			}
+		})
+	}
+}
+
+func TestAccessLogPreservesPanic(t *testing.T) {
+	for _, status := range []int{0, 201} {
+		t.Run(http.StatusText(status), func(t *testing.T) {
+			output := captureLogs(t)
+			handler := logging.AccessLog(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
+				if status != 0 {
+					w.WriteHeader(status)
+				}
+				panic("private-panic-value")
+			}))
+			func() {
+				defer func() {
+					if recovered := recover(); recovered != "private-panic-value" {
+						t.Errorf("panic changed: %v", recovered)
+					}
+				}()
+				handler.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/", nil))
+				t.Error("panic was swallowed")
+			}()
+			if strings.Contains(output.String(), "private-panic-value") {
+				t.Fatal("access log leaked the panic value")
+			}
+			records := readLogs(t, output)
+			if len(records) != 1 || records[0]["msg"] != "http request aborted" || records[0]["level"] != "ERROR" || records[0]["status"] != float64(status) {
+				t.Fatalf("aborted request was misreported: %v", records)
+			}
+		})
+	}
+}
+
+func TestConcurrentRequestCorrelation(t *testing.T) {
+	output := captureLogs(t)
+	if logging.FromContext(context.Background()) != slog.Default() {
+		t.Fatal("non-request context must use the default logger")
+	}
+	mux := http.NewServeMux()
+	mux.HandleFunc("GET /records/{id}", func(w http.ResponseWriter, r *http.Request) {
+		ctx, cancel := context.WithCancel(r.Context())
+		defer cancel()
+		logging.FromContext(ctx).InfoContext(ctx, "business event")
+		w.WriteHeader(204)
+	})
+	handler := logging.AccessLog(mux)
+	const count = 40
+	requestIDs := make(chan string, count)
+	var group sync.WaitGroup
+	for range count {
+		group.Go(func() {
+			response := httptest.NewRecorder()
+			handler.ServeHTTP(response, httptest.NewRequest("GET", "/records/private-id", nil))
+			requestIDs <- response.Header().Get("X-Request-ID")
+		})
+	}
+	group.Wait()
+	close(requestIDs)
+	seen := make(map[string]bool)
+	for requestID := range requestIDs {
+		if requestID == "" || seen[requestID] {
+			t.Fatalf("missing or reused request ID: %q", requestID)
+		}
+		seen[requestID] = true
+	}
+	records := readLogs(t, output)
+	if len(records) != count*2 {
+		t.Fatalf("log count = %d, want %d", len(records), count*2)
+	}
+	events := make(map[string]map[string]int)
+	for _, record := range records {
+		requestID, _ := record["request_id"].(string)
+		message, _ := record["msg"].(string)
+		if !seen[requestID] {
+			t.Fatalf("log has an unknown request ID: %v", record)
+		}
+		if events[requestID] == nil {
+			events[requestID] = make(map[string]int)
+		}
+		events[requestID][message]++
+	}
+	for requestID := range seen {
+		if events[requestID]["business event"] != 1 || events[requestID]["http request completed"] != 1 {
+			t.Errorf("incorrect correlation for %s: %v", requestID, events[requestID])
+		}
+	}
+}

backend/internal/logging/logging.go

@@ -0,0 +1,27 @@
+// Package logging centralizes JSON output and HTTP request correlation.
+// Callers must pass safe structured attributes, never credentials or raw
+// database/network errors that may contain private data.
+package logging
+
+import (
+	"context"
+	"io"
+	"log/slog"
+)
+
+type contextKey struct{}
+
+// New writes one JSON object per line to output at INFO level and above.
+// Use stdout in production so Docker and Alloy collect every application log.
+func New(output io.Writer) *slog.Logger {
+	return slog.New(slog.NewJSONHandler(output, nil))
+}
+
+// FromContext returns the request logger installed by AccessLog, or the default
+// logger outside HTTP requests. Derived contexts retain request correlation.
+func FromContext(ctx context.Context) *slog.Logger {
+	if logger, ok := ctx.Value(contextKey{}).(*slog.Logger); ok {
+		return logger
+	}
+	return slog.Default()
+}