feat(log): 全面重构日志系统，支持日志级别、去除ANSI乱码并抑制高频轮询

2026-09-18 15:04:38 +08:00
parent 20bde97d7a
commit ec76844da8
15 changed files with 415 additions and 100 deletions
@@ -1,12 +1,16 @@
 package router

 import (
+	"fmt"
 	"strings"
+	"time"

 	"affiliate_dash/internal/handler"
 	"affiliate_dash/internal/middleware"
 	"affiliate_dash/internal/model"
+	"affiliate_dash/internal/pkg/applog"
 	"affiliate_dash/internal/pkg/jwt"
+	"affiliate_dash/internal/pkg/openlog"
 	"affiliate_dash/internal/service"

 	"github.com/gin-contrib/cors"
@@ -64,15 +68,80 @@ func corsOrigins(h *Handlers) []string {
 	return origins
 }

-// requestLogger 访问日志中间件：跳过 /health 健康检查（每 30 秒一次，避免刷屏）。
+// isPollingEndpoint 判断是否属于高频轮询读接口
+func isPollingEndpoint(method, path string) bool {
+	if method != "GET" && method != "HEAD" {
+		return false
+	}
+	if path == "/health" {
+		return true
+	}
+	// 用户侧发货页轮询：绑定结果、订单详情、图片代理
+	if strings.HasPrefix(path, "/api/delivery/v1/orders/") {
+		return true
+	}
+	if strings.HasPrefix(path, "/api/delivery/v1/image-proxy") {
+		return true
+	}
+	// 商户开放平台轮询：订单详情、发货状态、钱包余额
+	if strings.HasPrefix(path, "/api/client/v1/orders/") && !strings.HasSuffix(path, "/cancel") {
+		return true
+	}
+	if path == "/api/client/v1/wallet" {
+		return true
+	}
+	// 源头侧查询订单
+	if strings.HasPrefix(path, "/api/open/v1/orders/") {
+		return true
+	}
+	return false
+}
+
+// requestLogger 结构化请求日志中间件：
+// 1. 无 ANSI 转义乱码
+// 2. 自动补充/透传 X-Request-ID
+// 3. 高频轮询请求（GET 且 200 成功）降为 DEBUG 级别，避免生产日志刷屏
+// 4. 写操作与状态变更（POST/PUT/DELETE）按 INFO 输出
+// 5. 错误请求（>=400）输出为 WARN/ERROR
 func requestLogger() gin.HandlerFunc {
-	inner := gin.Logger()
 	return func(c *gin.Context) {
-		if c.Request.URL.Path == "/health" {
-			c.Next()
-			return
+		reqID := c.GetHeader("X-Request-ID")
+		if reqID == "" {
+			reqID = openlog.GetReqID(c)
+		}
+		if reqID == "" || reqID == "-" {
+			reqID = openlog.EnsureReqID(c)
+		} else {
+			c.Set(openlog.CtxReqID, reqID)
+		}
+		c.Header("X-Request-ID", reqID)
+
+		start := time.Now()
+		c.Next()
+		latency := time.Since(start)
+
+		status := c.Writer.Status()
+		method := c.Request.Method
+		path := c.Request.URL.Path
+		ip := c.ClientIP()
+
+		var extra string
+		if mID := middleware.GetMerchantID(c); mID > 0 {
+			extra = fmt.Sprintf(" merchant_id=%d", mID)
+		}
+		if errStr := c.Errors.String(); errStr != "" {
+			extra += fmt.Sprintf(" err=%q", errStr)
+		}
+
+		if status >= 500 {
+			applog.Errorf("[HTTP] %d %s %s %v ip=%s req_id=%s%s", status, method, path, latency, ip, reqID, extra)
+		} else if status >= 400 {
+			applog.Warnf("[HTTP] %d %s %s %v ip=%s req_id=%s%s", status, method, path, latency, ip, reqID, extra)
+		} else if isPollingEndpoint(method, path) && latency < 3*time.Second {
+			applog.Debugf("[HTTP] %d %s %s %v ip=%s req_id=%s%s", status, method, path, latency, ip, reqID, extra)
+		} else {
+			applog.Infof("[HTTP] %d %s %s %v ip=%s req_id=%s%s", status, method, path, latency, ip, reqID, extra)
 		}
-		inner(c)
 	}
 }

@@ -1,10 +1,16 @@
 package router

 import (
+	"bytes"
+	"log"
+	"net/http/httptest"
+	"strings"
 	"testing"

 	"affiliate_dash/internal/handler"
+	"affiliate_dash/internal/pkg/applog"
 	"affiliate_dash/internal/pkg/jwt"
+	"affiliate_dash/internal/pkg/openlog"
 	"affiliate_dash/internal/service"
 	"affiliate_dash/internal/testdb"

@@ -49,3 +55,96 @@ func TestSetupDoesNotPanic(t *testing.T) {
 		OpenSignSkew:  300,
 	})
 }
+
+func TestIsPollingEndpoint(t *testing.T) {
+	tests := []struct {
+		method   string
+		path     string
+		expected bool
+	}{
+		{"GET", "/health", true},
+		{"GET", "/api/delivery/v1/orders/FO123/bind-result", true},
+		{"GET", "/api/delivery/v1/orders/FO123", true},
+		{"GET", "/api/client/v1/orders/FO123", true},
+		{"GET", "/api/client/v1/wallet", true},
+		{"GET", "/api/open/v1/orders/FO123", true},
+		{"POST", "/api/client/v1/orders", false},
+		{"POST", "/api/delivery/v1/orders/FO123/submit", false},
+		{"POST", "/api/client/v1/orders/FO123/cancel", false},
+		{"GET", "/api/dashboard", false},
+	}
+
+	for _, tc := range tests {
+		got := isPollingEndpoint(tc.method, tc.path)
+		if got != tc.expected {
+			t.Errorf("isPollingEndpoint(%s, %s) = %v, expected %v", tc.method, tc.path, got, tc.expected)
+		}
+	}
+}
+
+func TestRequestLoggerGeneratesAndPassesReqID(t *testing.T) {
+	gin.SetMode(gin.TestMode)
+	r := gin.New()
+	r.Use(requestLogger())
+	r.GET("/test", func(c *gin.Context) {
+		reqID := openlog.GetReqID(c)
+		if reqID == "" || reqID == "-" {
+			t.Errorf("expected req_id in context, got empty")
+		}
+		c.String(200, "ok")
+	})
+
+	req := httptest.NewRequest("GET", "/test", nil)
+	w := httptest.NewRecorder()
+	r.ServeHTTP(w, req)
+
+	respReqID := w.Header().Get("X-Request-ID")
+	if respReqID == "" {
+		t.Errorf("expected X-Request-ID in response header")
+	}
+}
+
+func TestRequestLoggerSuppressesPollingOnInfo(t *testing.T) {
+	gin.SetMode(gin.TestMode)
+	var buf bytes.Buffer
+	log.SetOutput(&buf)
+	defer log.SetOutput(log.Writer())
+
+	applog.SetLevel("info")
+
+	r := gin.New()
+	r.Use(requestLogger())
+	r.GET("/health", func(c *gin.Context) {
+		c.String(200, "ok")
+	})
+	r.GET("/api/client/v1/orders/:id", func(c *gin.Context) {
+		c.String(200, "ok")
+	})
+
+	// 1. In INFO level, polling requests with 200 should be silenced
+	buf.Reset()
+	req := httptest.NewRequest("GET", "/health", nil)
+	w := httptest.NewRecorder()
+	r.ServeHTTP(w, req)
+	if buf.Len() > 0 {
+		t.Errorf("expected /health 200 to be silenced in INFO mode, got: %s", buf.String())
+	}
+
+	buf.Reset()
+	req = httptest.NewRequest("GET", "/api/client/v1/orders/FO12345", nil)
+	w = httptest.NewRecorder()
+	r.ServeHTTP(w, req)
+	if buf.Len() > 0 {
+		t.Errorf("expected GET order 200 to be silenced in INFO mode, got: %s", buf.String())
+	}
+
+	// 2. In DEBUG level, polling requests should appear as [DEBUG]
+	applog.SetLevel("debug")
+	buf.Reset()
+	req = httptest.NewRequest("GET", "/api/client/v1/orders/FO12345", nil)
+	w = httptest.NewRecorder()
+	r.ServeHTTP(w, req)
+	if !strings.Contains(buf.String(), "[DEBUG] [HTTP] 200 GET /api/client/v1/orders/FO12345") {
+		t.Errorf("expected GET order to appear as [DEBUG] in DEBUG mode, got: %s", buf.String())
+	}
+}