feat(log): 落地统一日志底座与系统日志运维能力

backend/internal/server/middleware/client_request_id.go

@@ -2,10 +2,13 @@ package middleware
 
 import (
 	"context"
+	"strings"
 
 	"github.com/Wei-Shaw/sub2api/internal/pkg/ctxkey"
+	"github.com/Wei-Shaw/sub2api/internal/pkg/logger"
 	"github.com/gin-gonic/gin"
 	"github.com/google/uuid"
+	"go.uber.org/zap"
 )
 
 // ClientRequestID ensures every request has a unique client_request_id in request.Context().
@@ -24,7 +27,10 @@ func ClientRequestID() gin.HandlerFunc {
 		}
 
 		id := uuid.New().String()
-		c.Request = c.Request.WithContext(context.WithValue(c.Request.Context(), ctxkey.ClientRequestID, id))
+		ctx := context.WithValue(c.Request.Context(), ctxkey.ClientRequestID, id)
+		requestLogger := logger.FromContext(ctx).With(zap.String("client_request_id", strings.TrimSpace(id)))
+		ctx = logger.IntoContext(ctx, requestLogger)
+		c.Request = c.Request.WithContext(ctx)
 		c.Next()
 	}
 }

backend/internal/server/middleware/logger.go

@@ -1,10 +1,12 @@
 package middleware
 
 import (
-	"log"
 	"time"
 
+	"github.com/Wei-Shaw/sub2api/internal/pkg/ctxkey"
+	"github.com/Wei-Shaw/sub2api/internal/pkg/logger"
 	"github.com/gin-gonic/gin"
+	"go.uber.org/zap"
 )
 
 // Logger 请求日志中间件
@@ -24,38 +26,41 @@ func Logger() gin.HandlerFunc {
 			return
 		}
 
-		// 结束时间
 		endTime := time.Now()
-
-		// 执行时间
 		latency := endTime.Sub(startTime)
 
-		// 请求方法
 		method := c.Request.Method
-
-		// 状态码
 		statusCode := c.Writer.Status()
-
-		// 客户端IP
 		clientIP := c.ClientIP()
-
-		// 协议版本
 		protocol := c.Request.Proto
+		accountID, hasAccountID := c.Request.Context().Value(ctxkey.AccountID).(int64)
+		platform, _ := c.Request.Context().Value(ctxkey.Platform).(string)
+		model, _ := c.Request.Context().Value(ctxkey.Model).(string)
 
-		// 日志格式: [时间] 状态码 | 延迟 | IP | 协议 | 方法 路径
-		log.Printf("[GIN] %v | %3d | %13v | %15s | %-6s | %-7s %s",
-			endTime.Format("2006/01/02 - 15:04:05"),
-			statusCode,
-			latency,
-			clientIP,
-			protocol,
-			method,
-			path,
-		)
+		fields := []zap.Field{
+			zap.String("component", "http.access"),
+			zap.Int("status_code", statusCode),
+			zap.Int64("latency_ms", latency.Milliseconds()),
+			zap.String("client_ip", clientIP),
+			zap.String("protocol", protocol),
+			zap.String("method", method),
+			zap.String("path", path),
+		}
+		if hasAccountID && accountID > 0 {
+			fields = append(fields, zap.Int64("account_id", accountID))
+		}
+		if platform != "" {
+			fields = append(fields, zap.String("platform", platform))
+		}
+		if model != "" {
+			fields = append(fields, zap.String("model", model))
+		}
+
+		l := logger.FromContext(c.Request.Context()).With(fields...)
+		l.Info("http request completed", zap.Time("completed_at", endTime))
 
-		// 如果有错误，额外记录错误信息
 		if len(c.Errors) > 0 {
-			log.Printf("[GIN] Errors: %v", c.Errors.String())
+			l.Warn("http request contains gin errors", zap.String("errors", c.Errors.String()))
 		}
 	}
 }

backend/internal/server/middleware/request_access_logger_test.go

@@ -0,0 +1,193 @@
+package middleware
+
+import (
+	"context"
+	"net/http"
+	"net/http/httptest"
+	"sync"
+	"testing"
+
+	"github.com/Wei-Shaw/sub2api/internal/pkg/ctxkey"
+	"github.com/Wei-Shaw/sub2api/internal/pkg/logger"
+	"github.com/gin-gonic/gin"
+)
+
+type testLogSink struct {
+	mu     sync.Mutex
+	events []*logger.LogEvent
+}
+
+func (s *testLogSink) WriteLogEvent(event *logger.LogEvent) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	s.events = append(s.events, event)
+}
+
+func (s *testLogSink) list() []*logger.LogEvent {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	out := make([]*logger.LogEvent, len(s.events))
+	copy(out, s.events)
+	return out
+}
+
+func initMiddlewareTestLogger(t *testing.T) *testLogSink {
+	t.Helper()
+	if err := logger.Init(logger.InitOptions{
+		Level:       "debug",
+		Format:      "json",
+		ServiceName: "sub2api",
+		Environment: "test",
+		Output: logger.OutputOptions{
+			ToStdout: false,
+			ToFile:   false,
+		},
+	}); err != nil {
+		t.Fatalf("init logger: %v", err)
+	}
+	sink := &testLogSink{}
+	logger.SetSink(sink)
+	t.Cleanup(func() {
+		logger.SetSink(nil)
+	})
+	return sink
+}
+
+func TestRequestLogger_GenerateAndPropagateRequestID(t *testing.T) {
+	gin.SetMode(gin.TestMode)
+	r := gin.New()
+	r.Use(RequestLogger())
+	r.GET("/t", func(c *gin.Context) {
+		reqID, ok := c.Request.Context().Value(ctxkey.RequestID).(string)
+		if !ok || reqID == "" {
+			t.Fatalf("request_id missing in context")
+		}
+		if got := c.Writer.Header().Get(requestIDHeader); got != reqID {
+			t.Fatalf("response header request_id mismatch, header=%q ctx=%q", got, reqID)
+		}
+		c.Status(http.StatusOK)
+	})
+
+	w := httptest.NewRecorder()
+	req := httptest.NewRequest(http.MethodGet, "/t", nil)
+	r.ServeHTTP(w, req)
+	if w.Code != http.StatusOK {
+		t.Fatalf("status=%d", w.Code)
+	}
+	if w.Header().Get(requestIDHeader) == "" {
+		t.Fatalf("X-Request-ID should be set")
+	}
+}
+
+func TestRequestLogger_KeepIncomingRequestID(t *testing.T) {
+	gin.SetMode(gin.TestMode)
+	r := gin.New()
+	r.Use(RequestLogger())
+	r.GET("/t", func(c *gin.Context) {
+		reqID, _ := c.Request.Context().Value(ctxkey.RequestID).(string)
+		if reqID != "rid-fixed" {
+			t.Fatalf("request_id=%q, want rid-fixed", reqID)
+		}
+		c.Status(http.StatusOK)
+	})
+
+	w := httptest.NewRecorder()
+	req := httptest.NewRequest(http.MethodGet, "/t", nil)
+	req.Header.Set(requestIDHeader, "rid-fixed")
+	r.ServeHTTP(w, req)
+	if w.Code != http.StatusOK {
+		t.Fatalf("status=%d", w.Code)
+	}
+	if got := w.Header().Get(requestIDHeader); got != "rid-fixed" {
+		t.Fatalf("header=%q, want rid-fixed", got)
+	}
+}
+
+func TestLogger_AccessLogIncludesCoreFields(t *testing.T) {
+	gin.SetMode(gin.TestMode)
+	sink := initMiddlewareTestLogger(t)
+
+	r := gin.New()
+	r.Use(Logger())
+	r.Use(func(c *gin.Context) {
+		ctx := c.Request.Context()
+		ctx = context.WithValue(ctx, ctxkey.AccountID, int64(101))
+		ctx = context.WithValue(ctx, ctxkey.Platform, "openai")
+		ctx = context.WithValue(ctx, ctxkey.Model, "gpt-5")
+		c.Request = c.Request.WithContext(ctx)
+		c.Next()
+	})
+	r.GET("/api/test", func(c *gin.Context) {
+		c.Status(http.StatusCreated)
+	})
+
+	w := httptest.NewRecorder()
+	req := httptest.NewRequest(http.MethodGet, "/api/test", nil)
+	r.ServeHTTP(w, req)
+	if w.Code != http.StatusCreated {
+		t.Fatalf("status=%d", w.Code)
+	}
+
+	events := sink.list()
+	if len(events) == 0 {
+		t.Fatalf("expected at least one log event")
+	}
+	found := false
+	for _, event := range events {
+		if event == nil || event.Message != "http request completed" {
+			continue
+		}
+		found = true
+		switch v := event.Fields["status_code"].(type) {
+		case int:
+			if v != http.StatusCreated {
+				t.Fatalf("status_code field mismatch: %v", v)
+			}
+		case int64:
+			if v != int64(http.StatusCreated) {
+				t.Fatalf("status_code field mismatch: %v", v)
+			}
+		default:
+			t.Fatalf("status_code type mismatch: %T", v)
+		}
+		switch v := event.Fields["account_id"].(type) {
+		case int64:
+			if v != 101 {
+				t.Fatalf("account_id field mismatch: %v", v)
+			}
+		case int:
+			if v != 101 {
+				t.Fatalf("account_id field mismatch: %v", v)
+			}
+		default:
+			t.Fatalf("account_id type mismatch: %T", v)
+		}
+		if event.Fields["platform"] != "openai" || event.Fields["model"] != "gpt-5" {
+			t.Fatalf("platform/model mismatch: %+v", event.Fields)
+		}
+	}
+	if !found {
+		t.Fatalf("access log event not found")
+	}
+}
+
+func TestLogger_HealthPathSkipped(t *testing.T) {
+	gin.SetMode(gin.TestMode)
+	sink := initMiddlewareTestLogger(t)
+
+	r := gin.New()
+	r.Use(Logger())
+	r.GET("/health", func(c *gin.Context) {
+		c.Status(http.StatusOK)
+	})
+
+	w := httptest.NewRecorder()
+	req := httptest.NewRequest(http.MethodGet, "/health", nil)
+	r.ServeHTTP(w, req)
+	if w.Code != http.StatusOK {
+		t.Fatalf("status=%d", w.Code)
+	}
+	if len(sink.list()) != 0 {
+		t.Fatalf("health endpoint should not write access log")
+	}
+}

backend/internal/server/middleware/request_logger.go

@@ -0,0 +1,45 @@
+package middleware
+
+import (
+	"context"
+	"strings"
+
+	"github.com/Wei-Shaw/sub2api/internal/pkg/ctxkey"
+	"github.com/Wei-Shaw/sub2api/internal/pkg/logger"
+	"github.com/gin-gonic/gin"
+	"github.com/google/uuid"
+	"go.uber.org/zap"
+)
+
+const requestIDHeader = "X-Request-ID"
+
+// RequestLogger 在请求入口注入 request-scoped logger。
+func RequestLogger() gin.HandlerFunc {
+	return func(c *gin.Context) {
+		if c.Request == nil {
+			c.Next()
+			return
+		}
+
+		requestID := strings.TrimSpace(c.GetHeader(requestIDHeader))
+		if requestID == "" {
+			requestID = uuid.NewString()
+		}
+		c.Header(requestIDHeader, requestID)
+
+		ctx := context.WithValue(c.Request.Context(), ctxkey.RequestID, requestID)
+		clientRequestID, _ := ctx.Value(ctxkey.ClientRequestID).(string)
+
+		requestLogger := logger.With(
+			zap.String("component", "http"),
+			zap.String("request_id", requestID),
+			zap.String("client_request_id", strings.TrimSpace(clientRequestID)),
+			zap.String("path", c.Request.URL.Path),
+			zap.String("method", c.Request.Method),
+		)
+
+		ctx = logger.IntoContext(ctx, requestLogger)
+		c.Request = c.Request.WithContext(ctx)
+		c.Next()
+	}
+}